UPDATED: Serious Time Machine bug on Mountain Lion

A couple of notes about the tiny app on Pondini's web site:

1. It is intended for Mountain Lion users only. It may or may not work as expected on earlier OS versions.

2. It it is just a simple AppleScript application. If you want to check it out before running it to make sure it doesn't do anything sneaky, you can drop it on the AppleScript Editor icon (it is in the Utilities folder in the root level Applications folder). That will open the script itself in an editor window, so you can see exactly how it does what it does.

3. If you open it in the editor, I suggest that you not make any changes unless you have at least a basic understanding of AppleScript commands.

OK, here's some data points that may be useful. I wrote a small Applescript to monitor the

com.apple.TimeMachine.plist file every 10 seconds, and to copy it to another location if the timestamp had changed. I hoped to capture whatever is happening to the .plist.

What I have discovered is that some process, probably part of the Time Machine system itself, changes the .plist file by deleting the IncludeByPath section (which lists /Applications, /Library, /System, /bin, /private, /sbin and /usr) and moving those entries to the ExcludeByPath section. Shortly afterward (about 15 seconds), the file changes again, and the IncludeByPath section is restored. This does not happen with every backup, but it does happen regularly. And it happens when I am nowhere near the MacBook, so it must be a process that is active long-term.

This might possibly be absolutely routine, but it's odd. I wonder what might happen if the backup process gets interrupted, e.g. if you put the Mac to sleep. If the .plist file was to stay in the 'excluded' state for any reason, the next backup would remove those paths, but the process would also restore the file to the correct state, so the following backup run would include them again and do a full backup.

I tried deleting & recreating the .plist - it makes no difference. The file still gets changed to ExcludeByPath and then back to IncludeByPath.

Pondini wrote:

Absolutely. Backupd does update it, of course, {...} But I can't imagine why it needs to be that frequent.

On my system (which is not affected by the bug) /Library/Preferences/com.apple.TimeMachine.plist is apparently completely replaced (not modified) several times at or around the time of each backup, & perhaps more often than that.

I haven't tried a script to monitor this; instead I used a much cruder technique of opening a Finder 'get info' window for the file & then doing a 'back up now' from the TM menu item. To my surprise, not only did the get info window vanish immediately (presumably because the old file was deleted or overwritten), it vanished several times after that when I repeatedly opened the 'get info' window as fast as I could.

All this happened very quickly. I estimate the file got replaced at least three times over a period of no more that 2-3 seconds.

Note: this may or may not have anything to do with anything, but essentially all my backups, manual or automatic, start with a "backup failed with error 19" message in the log, followed by a successful backup. I believe this is because my backup drive spins down when not in use & it takes a few seconds for it to spin up each time a backup is done.

Pondini wrote:

Does this happen only when a backup is running?

Yes, as far as I can tell - i.e. I have watched it happen during a backup, and haven't seen it at any other time.

Do you have anything else in the ExcludeByPath section besides the 7 top-level libraries (as in the sample below)? If so, what?

In my original .plist, yes, there are additional entries which are always there:

However, there is nothing in the new .plist I created, apart from when it temporarily changes the IncludeByPath to ExcludeByPath. So I think the presence of other entries in ExcludeByPath is a red herring.

Absolutely. Backupd does update it, of course, with the results:

Fair enough - but why does it (or some other process) need to exclude all those directories from the backup, and then put them back in? It's daft. And it's possible that another background process updates the file. I wish I knew a way to determine what process wrote it.

Pondini wrote:

But that's my point -- something as simple as a misspelling, or reference to the wrong variable, in some piece of code that's only used in some fairly unusual circumstances, might be the culprit.

Yeah, but as I said, when I deleted the .plist and let Sys Prefs create a new one, the new 'clean' version still gets ine Exclude/Include flip-flop. So, the presence of the other entries doesn't seem to affect that. However, I take your point, and will see whether the new .plist still generates the mega backups.

Unfortunately, I wasn't able to test it last night because I had difficulty getting backupd to open the .sparseimage file - turns out one of the special characters in my .sparseimage password doesn't play nicely with Mountain Lion when you enter it manually. I created the file and stored the password in my keychain under a previous OS; when I tried to check it last night, Keychain Access was unable to display it ("Error creating UTF-8 encoded string from password data!"). I used hdiutil to change it to a textual password, then backupd could mount the image - but I ran out of time to do an actual backup. Will let you know...

Pondini wrote:

Does the speculation in my previous post make any sense?

Sure ... as much as anything else about this bug does. 😕

BTW, I have a Console log query set up to show every message with "backupd" in it, & I do not see any strict correlation between the time of logged com.apple.backud entries & when the plist file is rewritten.

Very odd.

I'll take a look at fseventr - but I've found something that might make the changes to the Time Machine .plist files:

CFPreferences Plist Files

The on-disk property list files used by CFPreferences have always been a private implementation detail, but in previous releases, directly modifying them has mostly worked (though there are some potential data-loss issues for applications that do so, even on previous systems). In 10.8 and later, the CFPreferences agent process (cfprefsd) will cache information from these files and asynchronously write to them. This means that directly modifying plist files is unlikely to have the expected results (new settings will not necessarily be read, and may even be overwritten).

I think what this is saying is that, in Mountain Lion, .plist files should not be modified directly. Instead, you call a CFPreferences API to request the changes, and cfprefsd carries them out. This blog post seems to confirm that:

http://rixstep.com/2/2/20130225,00.shtml

So the changes to com.apple.TimeMachine.plist are probably being made by cfprefsd.

Pondini wrote:

Still doesn't explain the frequent updates, does it?

Weird.

I suspect until we figure out why that happens (even on systems with no sign of the bug) we will just be floundering around in the dark.

Ross Barkman wrote:

I think what this is saying is that, in Mountain Lion, .plist files should not be modified directly. Instead, you call a CFPreferences API to request the changes, and cfprefsd carries them out.

My take on it is cfprefsd is just the defaults server, the daemon that implements default write commands. But if a process isn't running that would potentially overwrite manual changes to plist files, I can't see how it matters.

I certainly could be wrong about that, but I haven't noticed any changes in plist files I've changed manually, as long as I have made sure to kill any processes that might 'undo' my changes beforehand.