UPDATED: Serious Time Machine bug on Mountain Lion

Pondini wrote:

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

Weird.

Well...think I've found something.

I wondered why the changes get made at a time when backupd isn't logging anything to the console. So I had a look at the more detailed system.log. The timestamp on one of my "important paths in ExcludeByPath" versions of the files is timed at 20:24:32 - this is what appears on the log:

Aug 27 20:24:32 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'system.install.apple-software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/

installd' [41214] for authorization created by '/usr/sbin/installer' [41196] (4,0)

Aug 27 20:24:32 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'system.install.software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/

installd' [41214] for authorization created by '/usr/sbin/installer' [41196] (4,0)

Aug 27 20:24:32 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11] (100012,0)

The next version of the .plist, with all the important paths back in IncludeByPath, is timestamped 20:24:45 - the only SysLog entry is:

Aug 27 20:24:45 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11] (100012,0)

Then I looked at another pair of Exclude/Include .plists. The Exclude at 23:25:15 has this matching SysLog entries:

Aug 27 23:25:14 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'system.install.apple-software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/

installd' [69747] for authorization created by '/usr/sbin/installer' [69718] (4,0)

Aug 27 23:25:14 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'system.install.software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/

installd' [69747] for authorization created by '/usr/sbin/installer' [69718] (4,0)

Aug 27 23:25:15 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11] (100012,0)

The Include at 23:25:30 has this:

Aug 27 23:25:30 MBPro-11.local com.apple.SecurityServer[15]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11] (100012,0)

I think we have a winner. Acording to its man page:

The UserEventAgent utility is a daemon that loads system-provided plugins

to handle high-level system events which cannot be monitored directly by

launchd(8).

A little more digging tells us that these plugins are in /System/Library/UserEventPlugins/ - within that folder, there are two Time Machine plugins

com.apple.TimeMachine.plugin

com.apple.TimeMachine.System.plugin

Both of these are bundles containing executables, so I can't (yet) see inside them.

Now, installd is apparently the daemon for Software Update. Whether:

• installd needs to turn off Time Machine processing of major paths while it does a periodic check, so it tells UserEventAgent to move them to ExcludeByPath, then tells it to switch them back once it's done; or
• installd and UserEvent agent are both kicked off regularly by launchd, and one of UserEventAgent's tasks is to 'do stuff' to the Time Machine .plist; or
• UserEventAgent is called by backupd to 'do stuff'

...I dunno. Right now, I'm too sleepy to dig further.

Ok, tried fseventer today - I can confirm that all changes to com.apple.TimeMachine.plist that I've picked up using fseventer were carried out by cfprefsd. Of course, that doesn't tell us a lot - it's just a tool for safely changing .plists. The process that requested those changes is probably UserEventAgent, based on the log entries that show it getting permission to 'modify daemons', by which I assume it means to modify the settings for daemons such as backupd.

And it appears it creates temporary versions first, called com.apple.TimeMachine.plist.AQUWMNB snd such like, then does two chown commands to change ownership & access permisions, before renaming it to com.apple.TimeMachine.plist and resumably thus overwriting the previous file - then it modifies the file further.

Another update - had a mega-backup last night, using the 'clean' .plist. So deleting the .plist had no effect, meaning the additional ExcludeByPath entries in the original file had no bearing on the problem.

Yeah, was just wondering (originally) whether one of the 3rd-party entries was the problem, but not so.

I haven't determined any pattern to the occurrences - it happens regularly but randomly, often when I'm not even using the MacBook. All the .plist tracking I've done shows that the .plist file gets changed to ExcludeByPath for Applications, etc., for about 10 seconds in most (but not all) backup sessions. Why? Who knows?

So, I am just finding this tonight as a "victim" of this bug. I'll give a little background data here, and am already following http://pondini.org/TM/D10r.html to restore my lost Mac Pro.

So, last night my Mac Pro rebooted after I installed a USB driver (for an unimportant to this issue reason), and failed to boot. Research today shows that _both_ of my AppleRaid drives had failed. Rebooting into my BootCamp windows to run SeaTools showed they were okay in SMART, but failed any test I asked them to run. My pet peve about how Apple's software RAID doesn't seem to _tell_ me when one drive fails is not directly related to this forum thread. (I nearly had this same issue more than a year ago, but accidentally noticed a failed disk when running Disk Utility for another reason)

So, after [mostly] giving up on ressurecting the disks, I started to follow a process to restore from my Time Capsule, with which we've had a number of issues, but I've been very sure in recent days to see was doing it's job. I was surprised to find when I tried to restore from it via Mountain Lion boot USB, that there were two backups listed. November 4, 2012, and November 20, 2012. (10.8.2. Of course I have been running 10.8.4 for quite some time...) Thus the hours long research project that brought me to the previous thread to this one, and then this one. I haven't read _all_ of it, but I got through much of July before skipping to the end. :-)

So, as noted, I'm pursuing #10r, seeing no other option, which will hopefully get most of my data back. I can reinstall any Applications I need, the data in my home directory is more important to me to be "very up to date".

I have two other mac's, both Macbook Pro's, and I've just checked the one I'm on and it's /Library/Preferences/com.apple.TimeMachine.plist seems to have no ExcludeByPath, and has the expected paths in IncludeByPath. I can/will check the other Macbook Pro as well, though as noted, there're some other issues with our Time Capsule (adding an external drive seemed like such a good idea, but it's _never_ worked very reliably) that have caused issues on that end, too.

If you have any advice that's not in #10r from your site, or suggestions on what to do to keep track of this in the future, I'd love to hear them. (Mostly, I think I've read about so many people doing automated monitoring and recording, I'd love for a couple good pointers as to recommended tools and practices, both to help investigations, and to CMA.)

Thanks for the information here, and at http://pondini.org/TM/.

Pondini wrote:

Aha! That sounds like a MAJOR CLUE to me. 🙂

Surely there's no reason for them to be excluded for any significant time, if ever.

But if they do need to be excluded for an instant, then the problem is with whatever is supposed to return them to IncludeByPath.

Even better, it's clearly OSX, not any 3rd-party app(s).

Hmmm, not sure we can say that - it appears cfprefsd makes the change, but we don't know what process requests the change. We have a couple of suspects based on what I found in my SysLogs (installd and UserEventAgent), but it could be some other process. I agree it's unlikely to be a third-party app simply because of the level of permissions required to mess with System .plists, and because no request for access appears in the logs - but absence of evidence is not evidence of absence.

The other oddity is: I can't identify any time at which the .plist is left in the ExcludeByPath state for longer than 10s or so. So it's not like a backup completes and leaves the .plist in that state, so that the next backup deletes the Applications & other folders from the archive, then the next backup has to re-create them. At least, that's how it looks at present - I will monitor it more closely over the next few days. Part of the problem is that these enormous backups have now completely filled my Time Capsule, so every time it wants to do a mega backup, it deletes all the hourly snapshots, then deletes the oldest complete backup. So Backup Loupe doesn't see every snapshot, just a daily lump, unless I'm quick.

Can you make this happen at will? If so, do you have a Mac covered by Apple Care?

It makes itself happen at its own will - I'm just a passenger. As I said, pretty much every backup cycle I've captures shows the flipflop to ExcludeByPath and back to IncludeByPath. I'm pretty sure my AppleCare is still current, so will get on to Apple when I get the chance. I might wait until I'm sure that the .plist doesn't get left in the ExcludeByPath state at the end of a backup.

I haven't read all the threads, and don't use TM... but the folders seem to be those excluded by install_monitor during an install, including app store purchase/updates. There's a fixed list within install_monitor, and what may be a reference to InstallerTMExcludes.plist which perhaps has any extra items added, like say playready.

Install.log might point towards something misbehaving - perhaps a 'Temporarily excluding' not matched with a 'Re-included'.

That looks like a smoking gun.

Although I initially didn't understand why installd was doing anything, it turns out that it is regularly installing Sophos AV updates. If, as you say, one of those updates did not install cleanly, then the 'Re-include' step might not happen.

However, I think it is simpler than that. I've checked every exclude/include pair in install.log for the past 2 weeks (just put "clud" in the string-matching filter), and there are no unmatched excludes. But I have had a mega-backup during that period. My suspicion: if backupd happens to read the .plist file during the time that the major directories are excluded by installd, then it excludes them from the backup. Then the next backup has to re-include them.

OK, that's a pretty small window to hit: only 10-20 seconds during an installation. Now, installations are a pretty rare event, normally, but with Sophos's autoupdate running, they happen as frequently as once an hour. So now we have 20/3600 = 0.4% chance that a backup and an install will coincide. If there was an install every hour, the two would coincide once every 240 hours, i.e every 10 days, on average. In reality, Sophos updates are not that frequent, and we don't all leave our Macs running 24x7, so the interval will be longer - but it will happen.

I understand why installd does what it does - you don't want a backup that has a mix of an old and new version of a package, because it will be broken. If you restored from that backup, the app would not work. However, I think the approach used is a kludge that can be half-justified if you assume that installs are rare events, but falls apart when you have regular automatic installs. Basically, rather than installd excluding and re-including paths, backupd should just check whether installd is carrying out an install and delay the backup until it completes. Or a lockfile could be created by installd to tell backupd not to start a backup while installd is moving stuff around. Or some other handshaking mechanism. Just changing the .plist - that is sloppy programing.

SO: does anyone else having this problem have Sophos AV or any other AV package, or have some other app that has an autoupdate function - if you're not sure, open Console and check your var/logs/install.log file (you may have to scroll down the Log List sidebar quite a way to fing the install.log)