Log

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, from both stdout and stderr, is timestamped and written to a log file in backupdir/logs. If stdin is connected to a keyboard (you are running interactively from a keyboard or shell script), stdout and stderr are also displayed without a timestamp, as usual, and both are displayed on stdout, i.e. if you redirect stderr to a file with the log command, the file will be empty. If run from a cron job, all output is only written to the log file.

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 commands 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 (-x stands for context), 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 -x0 to get only the errors, since most errors include the pathname. For more context, use -x2 to see a couple of lines before and after each error.

-X strings - filters logs first by excluding lines containing any of the strings listed. For example:

-X "Copied arc."

excludes lines like "Copied arc.v.n to dest". The excludes are simple strings, not regular expressions, and multiple strings can be listed. Be sure to quote strings if they contain special characters like spaces.

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

  • returning a non-zero exit code when -s is used and any logs were summarized

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
01 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

Crontab entries are all one line. Some notes:

  • the first line is a comment documenting the next line

  • the job runs at 2:01am every day; this avoids a double run when Daylight Savings Time changes at 2am

  • 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

Finding Errors In Logs

If you need to find errors in large log files that have not been summarized with -x, it can be difficult if all of the backup pathnames are listed. The files can get so large that editors can’t load them.

To get a quick summary of errors in a log file, the command below displays all lines from the backup log that are not pathnames. -B1 shows the pathname 1 line before any error:

$ grep -v -B1 "| /" 2021-11-23_Tue_02\:00\:00_backup

2021-11-23 Tue 02:00:01| HashBackup #2527 Copyright 2009-2021 HashBackup, LLC
2021-11-23 Tue 02:00:01| Backup directory: /hbbackup
2021-11-23 Tue 02:00:01| Backup start: 2021-11-23 02:00:01
2021-11-23 Tue 02:00:01| Using destinations in dest.conf
2021-11-23 Tue 02:00:10| This is backup version: 3606
2021-11-23 Tue 02:00:12| Dedup enabled, 60% of current size, 12% of max size
--
2021-11-23 Tue 02:01:16| /Library
2021-11-23 Tue 02:01:16| Mount point contents skipped: /Network/Servers
--
2021-11-23 Tue 02:13:20| /Users
2021-11-23 Tue 02:13:20| Mount point contents skipped: /dev
2021-11-23 Tue 02:13:20| Mount point contents skipped: /home
2021-11-23 Tue 02:13:20| Mount point contents skipped: /net
--
2021-11-23 Tue 02:13:41| /
2021-11-23 Tue 02:13:46| Copied arc.3606.0 to usbcopy (12 MB 1s 11 MB/s)
2021-11-23 Tue 02:13:51| Waiting for destinations: b2

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:

$ 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 and re-zip the files. 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
HashBackup build #1945 Copyright 2009-2017 HashBackup, LLC

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

2017-05-06 Sat 02:00:01| HashBackup build #1890 Copyright 2009-2017 HashBackup, LLC
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:02| HashBackup build #1890 Copyright 2009-2017 HashBackup, LLC
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