User Confusion

Further research on my daily backup failing to run using anacron and Back In Time indicated that the system log file /var/log/syslog would provide some useful information. Since this file is typically quite large and contains thousands of lines of text (e.g. my current syslog file is 2.6 MB with 27,494 lines and more than half a million words!), clearly an efficient technique for handling this file is required.

One simple method is to load the file into gedit and use Ctrl-End to view the most recent log entries at the bottom of the file. A more sophisticated approach is to search, using grep, for a keyword of interest.

For example, we could see what the utilities anacron and cron are doing by using the Terminal command “grep cron /var/log/syslog”. This will display only the lines in the file that contain “cron” (and hence anacron). However, our previous tests have confirmed that anacron and cron are launching Back In Time, and the problem is somehow related to the configuration of the backup program. Consequently, it is more instructive to run “grep backintime /var/log/syslog” and limit the output to lines containing “backintime”. The most recent commands stored in the syslog file appear at the end of the listing and are thus displayed in the Terminal window.

The first test of this process is to run the grep command immediately after a regularly scheduled backup (using the Scheduled Tasks utility) of Back In Time has occurred. Grep produces quite a few lines of relevant output indicating the progress of the backup task, as follows:

Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Lock
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Include folders: [‘/media/DataDisk’]
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Ignore folders: []
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Last snapshots: {}
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: [GnomePlugin.Systray.run]
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: [GnomePlugin.Systray.run] begin loop
Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Compare with old snapshot: 20120911-074553
Sep 11 10:45:22 Dell-XPS8300 backintime (toaster): INFO: Command “rsync -aEAX -i –dry-run –chmod=Fa-w,D+w –whole-file –delete –exclude=”/media/Barracuda_01/z_images” –exclude=”/home/toaster/.local/share/backintime” –include=”/media/DataDisk/” –include=”/media/” –exclude=”.*” –exclude=”*.backup*” –exclude=”*~” –exclude=”/media/DataDisk/.Trash-1000″ –exclude=”/media/DataDisk/.sync.ffs_db” –include=”/media/DataDisk/**” –exclude=”*” / “/media/Barracuda_01/z_images/backintime/20120911-074553/backup/”” returns 0
Sep 11 10:45:22 Dell-XPS8300 backintime (toaster): INFO: Create hard-links
Sep 11 10:45:36 Dell-XPS8300 backintime (toaster): INFO: Command “cp -al “/media/Barracuda_01/z_images/backintime/20120911-074553/backup/”* “/media/Barracuda_01/z_images/backintime/new_snapshot/backup/”” returns 0
Sep 11 10:45:36 Dell-XPS8300 backintime (toaster): INFO: Call rsync to take the snapshot
Sep 11 10:45:39 Dell-XPS8300 backintime (toaster): INFO: Command “rsync -aEAX -v –delete-excluded –chmod=Fa-w,D+w –whole-file –delete –exclude=”/media/Barracuda_01/z_images” –exclude=”/home/toaster/.local/share/backintime” –include=”/media/DataDisk/” –include=”/media/” –exclude=”.*” –exclude=”*.backup*” –exclude=”*~” –exclude=”/media/DataDisk/.Trash-1000″ –exclude=”/media/DataDisk/.sync.ffs_db” –include=”/media/DataDisk/**” –exclude=”*” / “/media/Barracuda_01/z_images/backintime/new_snapshot/backup/”” returns 0
Sep 11 10:45:39 Dell-XPS8300 backintime (toaster): INFO: Save permissions
Sep 11 10:45:41 Dell-XPS8300 backintime (toaster): INFO: [GnomePlugin.Systray.run] end loop
Sep 11 10:45:41 Dell-XPS8300 backintime (toaster): INFO: Unlock

The above log entries indicate precisely how backintime processes the backup task. It first places some sort of lock on the system, identifies which folders are to be included and excluded, considers the contents of the previous snapshot, conducts a dry run of the backup process, creates any required hard links, runs rsync to perform the actual backup procedure and, finally, unlocks the system.

Compare this relatively verbose list of steps with the single log entry that results from running the backup script in the cron.daily folder under anacron:

Sep 11 11:10:23 Dell-XPS8300 backintime (unknown): WARNING: Not configured

Here is further confirmation that the problem is a configuration issue. But, it is also very instructive to compare the above line with the first line of the log entry for the successful job, namely:

Sep 11 10:45:01 Dell-XPS8300 backintime (toaster): INFO: Lock

In addition to the fact that the one task runs correctly, while the other fails with a warning, the huge clue that these two lines provide is that the successful job is running as the user “toaster” whereas for the failed job the user is “unknown”.

Clearly, Back In Time is confused about just who is running the program and, in particular, cannot locate a valid user configuration. So, perhaps all we need to do is tell it who we really are. But, how?

References:

LinuxLogFiles
https://help.ubuntu.com/community/LinuxLogFiles

Linux: Anacron tips
http://opensourceresearchtips.blogspot.ca/2012/01/linux-anacron-tips.html

Advertisements
This entry was posted in anacron, Applications, Backup, Bash script, Commands, cron and tagged . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s