Backups are wonderful things when they work. Two checks which you should perform routinely to ensure that your Time Machine backups will work when you expect them to, are verifying that backups are being made correctly in the first place, and every few weeks demonstrating that you can restore some files from your backup.

This tutorial shows how you can check that Time Machine backups are being made correctly.

In El Capitan and earlier, you could do this using the macOS Console app, as a great many users did. Since Sierra, when macOS switched to the new unified log, that has effectively been impossible. So I provide two free tools, T2M2 and Consolation, which together do the job even better than in the past. Both are available from their product page, and run in macOS from Sierra to Mojave.

Installing and using T2M2 should be pretty straightforward, but you might feel that Consolation 3 is a bit daunting, even with yesterday’s instructions and its documentation. Here I’ll walk you through using it from scratch.

Most days, I run T2M2 and get it to check the last 8-12 hours of backups. When I did that yesterday morning, it came up with a red warning because of an error message reported at 00:18:48, after I had gone to bed. Apart from that, it ran two deep traversal scans, which seems a bit unusual, but in spite of that made the expected auto backup every hour.

I copied that error message from T2M2 to a note, so that I could investigate what happened using Consolation, which I had reset as if I was using it for the first time. If you’ve already installed its custom styles and other settings, then you can skip the first steps in which I get it ready for use.

When you first run Consolation 3, it has no preference settings, and no custom styles, filters or predicates. The next thing to do is select the Log source as system, the Filter as Time Machine, and ensure the rest of its new document window is ready to use. It’s also worth ticking all the checkboxes in the Style section now, so that you get as many log entries as possible.

Although you don’t need all those custom settings, they’re going to be very useful here, so go to the Consolation3 app menu and select the Import custom settings… command. In the Open File dialog, locate the custom Property List supplied which is appropriate to the version of macOS which you’re running, and Open it.

Once that has been read in, you should find several new options in the Style popup menu, and those for saved predicate and filter. To ensure these are all written into Consolation’s preferences file, click on the Save as defaults button at the top right of the window.

The biggest problem when working with the unified log is getting an overwhelming volume of bafflingly detailed log entries, and it’s that which deters many users from accessing it. Consolation provides two important tools for dealing with this: filters to limit the type of entries shown, and the period to limit how long the extract will cover. Finding the right balance between those is a basic skill for working with the log now (as it always has been, to a lesser extent).

Consolation also provides several valuable controls which narrow the information down further, such as custom styles and filters. You’ll see how those can be used to make life easier here too.

First, let’s see the log extract which T2M2 analysed to produce its report. With the Filter set to Time Machine to limit the entries, select the basic or basic+ style, and set the period to 12 hour as above. Then click on the Get log button.

By opting for a custom style like basic+, rather than the built-in syslog or default styles, Consolation gets the log extract in JSON form, so that it’s fully structured. This means you can do a great deal with that extract without needing to click on Get log to obtain a fresh one.

You’ll now see a lot of log entries including plenty of failure reports and bewildering detail. If you’ve got a spare half hour, it can be interesting browsing through those, but T2M2 has already spared you that trouble. There are some simple things you can check without even having to get another log extract, though. Next, change the filter popup from none to success, to show the entries reporting successful completion of each backup.

To see the time when each backup started, switch the filter menu to use its regex search term *start^thinning.

It’s now time to hone in on the error we found in T2M2. To do that, set the period to 0, and enter the Start and End times for the log excerpt. With the Filter still set to Time Machine, pick a ten minute window around the time of the error, and click on Get log. Because you’ve altered the time period to be used, you’ll need to get that fresh log extract.

This gives the context in which Time Machine encountered that error: it occurred when Time Machine was making a backup, about 2 min 20 sec after that backup had started. The error itself looks like something prevented Time Machine from copying an App Store receipt file. You now need to look in closer detail at why that might have happened by viewing a wider range of log entries from the time of that error.

To look at all log entries, change the Filter from Time Machine to other text, leaving the text box next to it empty. Viewing those over a ten minute window will be pointless, so narrow the Start and End to a suitably short interval, centred on the time of the error. In Mojave, you can look at a window of just ten seconds; Sierra isn’t as good at such short periods, and for that you may have to broaden it, even to 30 seconds, perhaps. Then click on Get log.

The original error entry is now about five lines down. There’s nothing before it to indicate that it was precipitated by anything else. The entry after that is from Spotlight indexing and not relevant, but immediately below that is a very long explanation for the error, from the sandbox.

Until now, you’ve been using the basic+ style, which hides a lot of the information in each log entry. To see exactly what has happened, and who complained about it, switch the Style to starters+, which shows more of the fields. You may also want to uncheck the signposts and activities boxes to the right of Show, to reduce noise. This confirms it was a sandbox error involving the sandboxd service, which blocked copying a single file to the backup being made at the time.

At this point, I switch the Style to basic- to display entries which are easy to copy and paste in here. The error entries of concern are:
00:18:48.310196 Error: (-5000) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts/D0817AD589EB to /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106.inProgress/45C94758-152B-4846-9F71-D207A160C892/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts


00:18:48.319715 Sandbox: backupd(50377) System Policy: deny(1) forbidden-link-priv<file-map-executable> /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-223907/Macintosh HD/Applications/MarsEdit.localized/MarsEdit.app/Contents/_MASReceipt/receipt /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106.inProgress/45C94758-152B-4846-9F71-D207A160C892/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts/D0817AD589EB
Violation: System Policy: deny(1) […]
Process: backupd [50377] […]

So the error was the sandbox having a funny few moments over an App Store receipt, which is almost comfortingly trivial to know.

In practice, of course, I’d probably go straight for the ten second view of all log entries around the moment of the error, which takes just a few seconds, but sometimes you stumble into the middle of a viper’s nest, and this methodical approach should never fail you.

In the next tutorial, I’ll look at how to discover the cause of an app crashing when trying to open.