Log

Commands‎ > ‎

Runs an HB command with logging, usually as a cron job. The command to run immediately follows log, for example:

hb log backup -c backupdir (other backup options)

Each line of output from the command is timestamped and written to a log file in backupdir/logs.

The other use of hb log is to summarize and archive log files:

hb log -c backupdir -s [-e] [-d days] [-x lines]

This is also run as a cron job. To get summary output every time backup and retain are run, add hb log -s to the end of your backup & retain crontab line. Or, use a separate crontab line if you want the summary to be mailed on a different schedule, e.g., weekly.

-s summarize and archive log files. Log files are archived in .zip files by month.

-e only create output (send mail) if there are log files containing errors. If this option is not used, a short summary of program execution counts is mailed, unless HB has not been run and there are no log files.

-d days if it has been more than this many days since the last backup, an error will be included in the error summary

-x paths without this option (the default), all output from a command is included in the summary. For backups this can be extremely long because each modified pathname is listed, making it difficult to find just errors. With this option, only the number of paths before and after an error are included in the summary, as well as the normal backup output (statistics, etc). Use -x2 to make the summary easier to read and backup errors easy to find.

Cron Jobs, Logging, and Exit Code Handling

Normally a cron job will mail its output to userid root, or a MAILTO=blah@blah.com line can specify to mail it somewhere else. Most users will not want all of their backup output sent to them in email, but only the errors. The hb log command is designed to handle this by:

always exiting with a zero exit code, even if the program fails
redirecting all output to a log file in the backup directory
timestamping log filenames, like: 05-06_Sat_02:00:00_backup
using a filename suffix _FAIL when a command fails
using a filename suffix _RUN when a command is running or doesn't finish
timestamping every line of output to help resolve problems later

Typical Cron Job

Here's a typical system crontab entry for root to backup everything. Keep in mind that system crontab entries have an extra field, userid, that is not present in user crontab files.

# Min Hour DayOfMonth Month DayOfWeek User Command

00 02 * * * root /usr/local/bin/hb log backup -c /hbbackup /; /usr/local/bin/hb log retain -c /hbbackup -s30d12m -x3m; /usr/local/bin/hb log selftest -c /hbbackup -v4 --inc 1d/30d

This is all one line of course. Some notes:

the first line is a comment documenting the next line
the script runs at 2am every day
it backs up everything to /hbbackup
then runs retain to keep the last 30 days and a monthly backup for each month; deleted files are removed after 3 months (-x3m)
then runs selftest to check that the backup database is correct, and downloads and verifies (-v4) all arc files over a 30-day period (--inc 1d/30d)

To send a summary every day after the backup, whether there are errors or not, add this to the crontab line. Note that -e is not used:

/usr/local/bin/hb log -s -x2

To send a summary every day, but only if there are errors, add -e.

To send a summary once a week on Sunday at 7am, use a separate crontab entry:

00 07 * * Sun root /usr/local/bin/hb log -s -x2

Searching Log Files

Sometimes it's useful to search through old log files, for example, to find everything logged on a certain date or find all failed backups. This is easy from the command line if you know a trick: the unzip command takes a wildcard, but it has to be quoted.

Here's the log directory for these examples:

$ ls *.zip

2015-02.zip 2016-01.zip 2016-12.zip

2015-03.zip 2016-02.zip 2017-01.zip

2015-04.zip 2016-03.zip 2017-02.zip

2015-05.zip 2016-04.zip 2017-03.zip

2015-06.zip 2016-05.zip 2017-04.zip

2015-07.zip 2016-06.zip 2017-05.zip

2015-08.zip 2016-07.zip 2017-06.zip

2015-09.zip 2016-08.zip 2017-07.zip

2015-10.zip 2016-09.zip 2017-08.zip

2015-11.zip 2016-10.zip

2015-12.zip 2016-11.zip

Find all failed backups:

$ unzip -l '*.zip'|grep backup_FAIL

515 08-21-15 02:00 2015-08-21_Fri_02:00:00_backup_FAIL

515 08-22-15 02:00 2015-08-22_Sat_02:00:00_backup_FAIL

515 08-23-15 02:00 2015-08-23_Sun_02:00:01_backup_FAIL

515 08-24-15 02:00 2015-08-24_Mon_02:00:01_backup_FAIL

370 09-15-15 02:00 2015-09-15_Tue_02:00:01_backup_FAIL

370 09-16-15 02:00 2015-09-16_Wed_02:00:01_backup_FAIL

370 09-17-15 02:00 2015-09-17_Thu_02:00:01_backup_FAIL

370 09-18-15 02:00 2015-09-18_Fri_02:00:01_backup_FAIL

1828 01-02-16 02:00 2016-01-02_Sat_02:00:01_backup_FAIL

31178 05-06-17 02:04 2017-05-06_Sat_02:00:00_backup_FAIL

66374 05-07-17 02:10 2017-05-07_Sun_02:00:01_backup_FAIL

31 archives were successfully processed.

Find all failed backups in 2017:

$ unzip -l '*.zip'|grep '2017-.*backup_FAIL

515 08-21-15 02:00 2015-08-21_Fri_02:00:00_backup_FAIL

515 08-22-15 02:00 2015-08-22_Sat_02:00:00_backup_FAIL

515 08-23-15 02:00 2015-08-23_Sun_02:00:01_backup_FAIL

515 08-24-15 02:00 2015-08-24_Mon_02:00:01_backup_FAIL

370 09-15-15 02:00 2015-09-15_Tue_02:00:01_backup_FAIL

370 09-16-15 02:00 2015-09-16_Wed_02:00:01_backup_FAIL

370 09-17-15 02:00 2015-09-17_Thu_02:00:01_backup_FAIL

370 09-18-15 02:00 2015-09-18_Fri_02:00:01_backup_FAIL

1828 01-02-16 02:00 2016-01-02_Sat_02:00:01_backup_FAIL

31178 05-06-17 02:04 2017-05-06_Sat_02:00:00_backup_FAIL

66374 05-07-17 02:10 2017-05-07_Sun_02:00:01_backup_FAIL

31 archives were successfully processed.

Find all failed commands in March of 2017:

$ unzip -l '*.zip'|grep '2017-03.*FAIL'

1249 03-17-17 17:43 2017-03-17_Fri_17:42:58_retain_FAIL

889 03-17-17 17:51 2017-03-17_Fri_17:50:54_retain_FAIL

889 03-18-17 02:04 2017-03-18_Sat_02:03:33_retain_FAIL

31 archives were successfully processed.

Find all logs on 2017-08-01 (or just use unzip -l 2017-08):

$ unzip -l '*.zip'|grep 2017-08-01

9899 08-01-17 02:03 2017-08-01_Tue_02:00:00_backup

889 08-01-17 02:04 2017-08-01_Tue_02:03:27_retain

15205 08-01-17 02:07 2017-08-01_Tue_02:04:18_selftest

31 archives were successfully processed.

For a more complex example, suppose we want to regenerate the summary of backup errors for May 2017. The basic idea is to unzip (expand) the failed backup log files for that month, then run hb log again to regenerate the error summary. Like this:

$ cd /hbbackup/logs

$ unzip 2017-05 '*backup_FAIL'

Archive: 2017-05.zip

inflating: 2017-05-06_Sat_02:00:00_backup_FAIL

inflating: 2017-05-07_Sun_02:00:01_backup_FAIL

$ hb log -c /hbbackup -s -e -x2

==================== 2017-05-06_Sat_02:00:00_backup_FAIL

2017-05-06 Sat 02:00:02| Backup directory: /hbbackup

2017-05-06 Sat 02:00:07| Backup start: 2017-05-06 02:00:07

2017-05-06 Sat 02:00:08| This is backup version: 2079

2017-05-06 Sat 02:00:17| Dedup enabled, 12% of current, 1% of max

2017-05-06 Sat 02:00:17| /

2017-05-06 Sat 02:01:45| /Library/Caches

... (425 lines)

2017-05-06 Sat 02:04:00| /Users/jim/hbnew/fuse.py

2017-05-06 Sat 02:04:00| /Users/jim/hbnew/get.py

2017-05-06 Sat 02:04:00| Database error: no such column: paths.pathid

2017-05-06 Sat 02:04:00| Traceback (most recent call last):

2017-05-06 Sat 02:04:00| File "/hb.py", line 246, in <module>

2017-05-06 Sat 02:04:00| File "/db.py", line 522, in closedb

2017-05-06 Sat 02:04:00| sqlite3.OperationalError: unable to close due to unfinalized statements or unfinished backups

2017-05-06 Sat 02:04:00| Exit 1: Fail

==================== 2017-05-07_Sun_02:00:01_backup_FAIL

2017-05-07 Sun 02:00:04| Backup directory: /hbbackup

2017-05-07 Sun 02:00:10| Backup start: 2017-05-07 02:00:10

2017-05-07 Sun 02:00:11| This is backup version: 2079

2017-05-07 Sun 02:00:21| Dedup enabled, 12% of current, 1% of max

2017-05-07 Sun 02:00:22| /

2017-05-07 Sun 02:00:30| /.DS_Store

... (713 lines)

2017-05-07 Sun 02:10:23| /Users/jim/hbnew/fuse.py

2017-05-07 Sun 02:10:23| /Users/jim/hbnew/get.py

2017-05-07 Sun 02:10:23| Database error: no such column: paths.pathid

2017-05-07 Sun 02:10:23| Traceback (most recent call last):

2017-05-07 Sun 02:10:23| File "/hb.py", line 246, in <module>

2017-05-07 Sun 02:10:23| File "/db.py", line 522, in closedb

2017-05-07 Sun 02:10:23| sqlite3.OperationalError: unable to close due to unfinalized statements or unfinished backups

2017-05-07 Sun 02:10:23| Exit 1: Fail

Summary:

--------

backup failures: 2

Comments