Time Machine fails to backup FileVault home directory on logout

Question

I am using FileVault to encrypt my home directory, and Time Machine for backups. This is a typical workflow:

1. I am logged on. I plug in the USB hard disk drive that I am using for my Time Machine backups. I let Time Machine to run a backup (of everything else besides by home directory).

2. I log out. First, FileVault does its clean-up work, and then Time Machine starts to back up my encrypted home directory.

However, more often than not step 2 silently fails. Time Machine simply skips the backup. Everything looks fine, there are no error messages, and a casual user might not even notice anything unusual. It just looks as if Time Machine did its things quickly. But if you inspect the log file (or check what was actually copied to the backup disk), you will see that it simply skipped the part where it should have done the backup of the FileVault directory.

---

If everything works fine, the log files show something like this. Note that Time Machine actually runs two backups. I guess the first one is related to the FileVault home directory, while the second one is related to parts outside my home directory; the latter part was already up-to-date, so there are very few changes:

23:27:49    diskimages-helper[5309] Reclaimed 0 bytes out of 259.9 GB possible.
23:27:50    com.apple.backupd[5089] Starting standard backup
23:27:50    com.apple.backupd[5089] Backing up to: /Volumes/xxx/Backups.backupdb
23:27:53    com.apple.backupd[5089] No pre-backup thinning needed: 7.30 GB requested (including padding), 485.02 GB available
23:27:53    com.apple.backupd[5089] Indexer unavailable (200)
23:27:55    com.apple.backupd[5089] Indexer unavailable (200)
23:28:18    fseventsd[36]           Events arrived for /Volumes/xxx after an unmount request! Re-initializing.
23:31:19    com.apple.backupd[5089] Copied 272 files (6.1 GB) from volume Macintosh HD.
23:31:19    com.apple.backupd[5089] No pre-backup thinning needed: 100.0 MB requested (including padding), 478.94 GB available
23:31:19    com.apple.backupd[5089] Waiting for index to be ready (101)
23:31:23    com.apple.backupd[5089] Copied 50 files (93 bytes) from volume Macintosh HD.
23:31:23    com.apple.backupd[5089] Starting post-backup thinning
23:31:23    com.apple.backupd[5089] No post-back up thinning needed: no expired backups exist
23:31:23    com.apple.backupd[5089] Backup completed successfully.

And a failure looks like this: only the second backup was run:

23:26:35    diskimages-helper[5218] Reclaimed 0 bytes out of 259.9 GB possible.
23:26:36    com.apple.backupd[5089] Starting standard backup
23:26:36    com.apple.backupd[5089] Backing up to: /Volumes/xxx/Backups.backupdb
23:26:37    com.apple.backupd[5089] No pre-backup thinning needed: 100.0 MB requested (including padding), 485.02 GB available
23:26:37    com.apple.backupd[5089] Indexer unavailable (200)
23:26:39    com.apple.backupd[5089] Indexer unavailable (200)
23:26:40    com.apple.backupd[5089] Copied 184 files (8 KB) from volume Macintosh HD.
23:26:40    com.apple.backupd[5089] Starting post-backup thinning
23:26:40    com.apple.backupd[5089] No post-back up thinning needed: no expired backups exist
23:26:40    com.apple.backupd[5089] Backup completed successfully.

"Backup completed successfully" indeed. Just forgot to copy approx. 6GB of changes in my encrypted home directory.

In this case simply doing logon + logout fixed the problem and Time Machine started to backup it properly (resulting in the first log file snippet).

---

The obvious things like verifying the disks (source & destination) with Disk Utility do not help. The same thing has occurred with different versions of Mac OS X 10.6.x; currently I am using 10.6.7. Trying different USB hard disk drives, different USB ports, etc. does not help. I don't have anything fancy in my setup (other than using FileVault); the computer is a MacBook Pro.

Is this something unique that other people haven't seen, or is this a more common problem? Are there any solutions or workarounds? Of course using a different backup tool solves all these problems, but Time Machine would be convenient if it worked reliably...

Answer 1

It's not an answer to your specific intermittent failure, but I do have a workaround that several clients have used.

I make them another account that isn't file vault protected and rather than logging out and leaving the mac at the welcome screen, enter the empty user and walk away. (or kick off a backup and then walk away)

In practice I get better backups when a user is logged in.

If this needs to work for you, do file a bug with apple since it should work each time and every time without a workaround. When it fails, there should be detailed enough logging to fix issues if they arise even if normal logs are suppressed as a compromise to added security with FileVault enabled.

Also BackupLoupe is great for poking at backups to see what is actually changing after the fact rather than guessing from logs and byte counts stored in logs.

I have had other people reconsider file vault and just use encrypted disk images for data that needs to be secured which minimizes many of the drawbacks of having the entire user folder inside file vault. I've done this myself since soon after file vault came out and I much prefer it compared to living with FileVault.

Answer 2

The following workaround seems to help:

• Do not select "Back Up Now" in the Time Machine menu.
• Just wait until Time Machine starts a backup automatically.

Answer 3

I've been battling with the EXACT same problem for months now and it seemed random. Then I realised the answer is really simple:

Plug in your power cord and Time Machine will perform the backup upon logout (with the backup disk connected before logout of course). On battery power it won't. I wish Apple would document that clearly somewhere or warn you on logout (I'm on OS X 10.6.8).