Log

Summarize and compress HashBackup log files.

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

With no options:

log files in backupdir/logs are compressed into monthly .zip files named YYYY-MM.zip in the logs subdirectory
logs ending with _FAIL or _RUN are written to stderr
a short summary of log file counts is written to stderr
if errors are detected, log exits with a non-zero exit code

Options

-e only display errors. This suppresses the short summary of log file counts when everything is successful.

-d days an error is added to the error summary if it has been more than this many days since the last backup.

-x #lines restricts output from backup logs by removing most pathnames. Only the number of lines specified before and after an error are included, as well as the normal backup output (statistics, etc). Use -x0 to get only the errors, since most errors include the pathname. Use -x1 to include a line 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. Excludes are simple strings, not regular expressions, and multiple strings can be listed. Be sure to quote strings if they contain special characters or spaces.

Logging

Most HashBackup commands log their output in the local backup directory’s logs subdirectory. These logs files are very helpful to track down problems and summarize errors. The logging system:

sends all output and errors to log files in the backup directory
timestamps every line to help resolve problems later
timestamps log filenames: 2021-05-06_Sat_02:00:00_backup
adds a filename suffix _FAIL when a command fails
adds a filename suffix _RUN when a command is running or doesn’t finish

When summarizing log files, the log command:

compresses log files into monthly .zip archives named YYYY-MM.zip
writes error summaries to stderr
exits with a non-zero exit code if any errors are detected

Cron Jobs

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
MAILTO=me@email.com
01 00 * * * root nice sh -c "/usr/local/bin/hb backup -c /hbbackup /; /usr/local/bin/hb retain -c /hbbackup -s30d12m -x3m; /usr/local/bin/hb selftest -c /hbbackup -v4 --inc 1d/30d; /usr/local/bin/hb upgrade; /usr/local/bin/hb log -c /hbbackup -e -x1" >/dev/null

Crontab entries are all one line. Some notes:

the first line is a comment documenting the next line
errors are sent to me@email.com
the job runs at midnight every day
backs up everything (/) to /hbbackup
runs retain to keep 30 daily backups and a monthly backup for 12 months (-s30d12m); deleted files are removed after 3 months (-x3m)
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)
installs HashBackup upgrades
summarizes log files, notifies on errors (-e) and shows 1 line of context (-x1)

To send a summary every day after the backup, whether there are errors or not, remove -e from the hb log command.

To send a summary once a week on Sunday at 7am, remove the hb log command and use a separate crontab entry:

00 07 * * Sun root /usr/local/bin/hb log -c /hbbackup -x2 >/dev/null

Finding Backup Errors

It can be difficult to find errors in large backup log files when all of the backup pathnames are listed. The files can get so large that editors can’t load them.

For a quick summary of errors in a backup log file, the command below finds all lines that are not pathnames. -B1 shows the pathname 1 line before errors. Add -A1 to show the pathname 1 line after errors.

$ 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 Zipped Logs

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

Keep in mind the zip wildcard is for a filename, so it is a glob wildcard and * means "zero or more characters". However, grep uses regular expressions, so .* is used.

$ unzip -l '*.zip'|grep '2017-.*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.`

Summarize backup errors for May 2017

For a more complex example, suppose we want to see 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 show 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 -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