You can make a difference in the Apple Support Community!

When you sign up with your Apple Account, you can provide valuable feedback to other community members by upvoting helpful replies and User Tips.

Looks like no one’s replied in a while. To start the conversation again, simply ask a new question.

UPDATED: Serious Time Machine bug on Mountain Lion

This is continued and summarized from a previous thread, Serious Time Machine bug on Mountain Lion, which has grown rather large and unwieldy (and which I marked Solved in error). There are a few other threads that touch on it as well.



Some of us have seen a few cases of a pretty nasty problem with Time Machine backups on Mountain Lion. It doesn't seem to affect a lot of users, but those who have it, don't know it. It seems to have started at different times for different users, some as long ago as December, 2012.


The backups cannot not be used to do a full system restore from recent backups -- they don't appear on the selection screen that shows only "complete" backups. Plus, they're not recognized as backups by Setup Assistant or Migration Assistant. They don't appear on the Select the Source or Select Your System windows at all. But your user data is fine via the Time Machine browser (the "Star Wars" display).


What's happening is, the top-level Applications, Library, System and (hidden) private folders are being excluded by some process (not the user, and the exclusions do not appear on the Time Machine Preferences window). But all backups complete normally, and Verify Backups from the Time Machine menubar on network backups, and Verify Disk or Repair Disk via Disk Utility, don't show a problem (because what's there is intact; those processes can't tell that what's missing isn't supposed to be missing.)


In addition, we've seen a few threads where the problem is intermittent -- backups are unexpectedly large, sometimes often, sometimes less so, intermittently. In those cases, the folders are backed up, then skipped, then backed-up again, then skipped, etc. Since they appear to be "new" when backed-up again, they're backed-up in full, making backups of 15 GB or more.



See #D10 in Time Machine - Troubleshooting for an easy way to tell if you're affected, and a fix.


However, as we have no clue as to the cause yet, we need to be sure Apple knows about this, in detail, while it's happening, so I'm asking for some folks who are having these problems, and are fairly comfortable with the Finder at least, and following directions to do other things you may not be so familiar with, to help us collect information and contact Apple before running the fix in the link above (as that will destroy some of the evidence).


We're especially interested in folks who are covered by AppleCare, as you can call them for free and get some fairly quick attention. We can supply some "ammunition" for when you call them (since I haven't had this problem, and don't know how to reproduce it, I can't report it myself).



If you're having this problem and just want to run the fix, by all means do so (and check it periodically), but please don't post back with just a "me, too" post, unless you have something significant to add -- this thread may get long and those won't really help.


But if you're having a different problem, please do not respond to this thread. Start a new one, instead. If you're not sure how to do that, please go to the main Apple Support Communities page; some Tutorials are listed at the right. They'll show you how to get started.

Posted on Jun 24, 2013 6:48 AM

Reply
171 replies

Sep 4, 2013 5:09 PM in response to Ross Barkman

The more I see, the confuseder I get. 😉


If it's specifically suspending the backup:


Sep 4 16:03:11 JPsiMac10v8.local installd[1588]: PackageKit: suspending backupd


why does it need to fool with exclusions at all?



the approach used is a kludge


It would seem much safer to just suspend backupd -- if something goes wrong and the Install fails, when backupd gets restarted, it will just keep on doing what it was supposed to do.


Clearly, too simple a solution. 👿

Sep 5, 2013 4:31 AM in response to andyBall_uk

Yeah, that's a reasonable supposition, but I have zero evidence of it. I'm running an AppleScript that monitors the modification date on com.apple.TimeMachine.plist, and copies it to another folder (with appropriate name change) every time it detects a modification. To avoid thrashing the system, it checks every second rather than continuously, but it ought to catch the final state of the .plist after each backup and after each installd run.


As I type, backupd is doing one of its mega-backups of Applications, etc. That should mean I can find a .plist version sometime in the last few hours that has ExcludeByPath with no following IncludeByPath. However, the pattern looks like this:



20:36:09 Exclude

20:36:24 Include


20:47:07 Include

20:47:19 Include


21:52:25 Include

21:53:03 Include


22:48:58 Include

22:49:25 Include


23:37:03 Exclude

23:37:20 Include


23:57:02 Include

23:57:17 Include


09:27:10 Include

09:28:12 Exclude

09:28:28 Include


10:28:55 Exclude

10:29:08 Include


So I don't see any Excludes that aren't matched by an Include. However, I've picked up something else.


backupd ran at 00:36:11 last night (log entries shortened for brevity/security:


Sep 5 00:36:11 MBPro-11.local com.apple.backupd[60876]: Starting automatic backup

Sep 5 00:36:11 MBPro-11.local com.apple.backupd[60876]: Attempting to mount network destination URL

Sep 5 00:36:11 MBPro-11.local com.apple.backupd[60876]: Mounted network destination at mount point

Sep 5 00:36:48 MBPro-11.local com.apple.backupd[60876]: Disk image mounted at: /Volumes/Time Machine Backups

Sep 5 00:36:48 MBPro-11.local com.apple.backupd[60876]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb

Sep 5 00:36:59 MBPro-11.local com.apple.backupd[60876]: Using file event preflight for Hard Disk

Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: Will copy (9.7 MB) from Hard Disk

Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: Found 89 files (9.7 MB) needing backup

Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: 3.26 GB required (including padding), 9.24 GB available


However, I put the system to sleep at 01:13, and it appears that backup had not completed by then - which is crazy, if it was only backing up 9.7MB. Nevertheless, this morning, the log shows:


Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Backup failed because the destination disk was ejected or disconnected unexpectedly!

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: couldn't determine volume-uuid of mount point:

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Backup canceled.

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: [SnapshotUtilities mountPointForVolumeRef] FSGetVolumeInfo returned: -35

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Failed to eject volume (null) (FSVolumeRefNum: -392; status: -35; dissenting pid: -1)

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Failed to eject Time Machine disk image:


Then it starts the mega-backup:


Sep 5 09:30:38 MBPro-11.local com.apple.backupd[69993]: Starting automatic backup

Sep 5 09:30:38 MBPro-11.local com.apple.backupd[69993]: Attempting to mount network destination URL:

Sep 5 09:30:39 MBPro-11.local com.apple.backupd[69993]: Mounted network destination at mount point:

Sep 5 09:32:30 MBPro-11.local com.apple.backupd[69993]: Disk image mounted at: /Volumes/Time Machine Backups

Sep 5 09:32:30 MBPro-11.local com.apple.backupd[69993]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb

Sep 5 09:33:03 MBPro-11.local com.apple.backupd[69993]: Waiting for index to be ready (100)

Sep 5 09:34:04 MBPro-11.local com.apple.backupd[69993]: Waiting for index to be ready (100)

Sep 5 09:34:33 MBPro-11.local com.apple.backupd[69993]: Using file event preflight for Hard Disk

Sep 5 09:34:43 MBPro-11.local com.apple.backupd[69993]: Will copy (76.5 MB) from Hard Disk

Sep 5 09:34:43 MBPro-11.local com.apple.backupd[69993]: Found 2689 files (113.6 MB) needing backup

Sep 5 09:34:50 MBPro-11.local com.apple.backupd[69993]: 3.38 GB required (including padding), 5.71 GB available

Sep 5 10:33:07 MBPro-11.local com.apple.backupd[69993]: Copied 5.6 GB of 5.6 GB, 141394 of 141394 items

Sep 5 11:33:07 MBPro-11.local com.apple.backupd[69993]: Copied 13.79 GB of 13.79 GB, 227289 of 227289 items

Sep 5 12:22:28 MBPro-11.local com.apple.backupd[69993]: Copied 483784 files (18.75 GB) from volume Hard Disk.


It's still running now, doing an extra backup of anythng that's changed since 09:30. So, how did "Found 2689 files (113.6 MB) needing backup" suddently turn into "Copied 483784 files (18.75 GB)" ?????? It didn't think it needed to backup all that stuff when it started - and installd ran before it at 09:28 and left the .plist in Include state, then didn't run again until 10:28, by which time backupd was well on its way to its first 5GB.


It looks like interrupting backupd is a Bad Idea - it's almost as if it loses its place and decides to back up everything, just in case.

Sep 5, 2013 4:57 AM in response to Ross Barkman

Ross Barkman wrote:

. . .

It's still running now, doing an extra backup of anythng that's changed since 09:30. So, how did "Found 2689 files (113.6 MB) needing backup" suddently turn into "Copied 483784 files (18.75 GB)" ??????

Could it be that you just triggered the bug? Do the folders in question add-up to anything in the area of 19 GBs?



It looks like interrupting backupd is a Bad Idea - it's almost as if it loses its place and decides to back up everything, just in case.

Usually, it's fine. Often does a deep scan, but pretty much just picks up where it left off.


Will be very interested to see what it's doing this time . . .

Sep 5, 2013 5:12 AM in response to Pondini

Pondini wrote:


Could it be that you just triggered the bug? Do the folders in question add-up to anything in the area of 19 GBs?


Yes, I guess I did - but how? Apart from interrupting the backup, presumably during a cleanup phase (since it was supposed to be a small backup, and I can't see any other reason for it not to be completed by 01:13 when it started at 00:36).


The folders do add up to that amount, based on previous mega-backups checked by Backup Loupe.


Will be very interested to see what it's doing this time . . .


It's finished now. Final log entries for backupd are:


Sep 5 12:22:32 MBPro-11.local com.apple.backupd[69993]: Using file event preflight for Hard Disk

Sep 5 12:22:38 MBPro-11.local com.apple.backupd[69993]: Will copy (15.2 MB) from Hard Disk

Sep 5 12:22:38 MBPro-11.local com.apple.backupd[69993]: Found 330 files (15.2 MB) needing backup

Sep 5 12:22:38 MBPro-11.local com.apple.backupd[69993]: 3.85 GB required (including padding), 14.85 GB available

Sep 5 12:26:37 MBPro-11.local com.apple.backupd[69993]: Copied 8310 files (28.7 MB) from volume Hard Disk.

Sep 5 12:26:43 MBPro-11.local com.apple.backupd[69993]: Created new backup: 2013-09-05-122641

Sep 5 12:28:18 MBPro-11.local com.apple.backupd[69993]: Starting post-backup thinning

Sep 5 12:35:39 MBPro-11.local com.apple.backupd[69993]: Deleted /Volumes/Time Machine Backups/Backups.backupdb/....... (128.4 MB)

Sep 5 12:35:39 MBPro-11.local com.apple.backupd[69993]: Post-back up thinning complete: 1 expired backups removed

Sep 5 12:35:43 MBPro-11.local com.apple.backupd[69993]: Backup completed successfully.

Sep 5 12:35:46 MBPro-11.local com.apple.backupd[69993]: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb

Sep 5 12:36:51 MBPro-11.local com.apple.backupd[69993]: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb

Sep 5 12:39:01 MBPro-11.local com.apple.backupd[69993]: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb

Sep 5 12:41:21 MBPro-11.local com.apple.backupd[69993]: Ejected Time Machine disk image:

Sep 5 12:41:22 MBPro-11.local com.apple.backupd[69993]: Ejected Time Machine network volume.

Sep 5, 2013 5:17 AM in response to Ross Barkman

Ross Barkman wrote:


Pondini wrote:


Could it be that you just triggered the bug? Do the folders in question add-up to anything in the area of 19 GBs?


Yes, I guess I did - but how? Apart from interrupting the backup, presumably during a cleanup phase (since it was supposed to be a small backup, and I can't see any other reason for it not to be completed by 01:13 when it started at 00:36).

Logical or not, it's a GREAT place to start. If you can replicate it, maybe I can; if I can, I can report it, and if AppleCare can replicate it, too, it'll go to the engineers.



The folders do add up to that amount, based on previous mega-backups checked by Backup Loupe.

What'll you bet they were excluded from the previous backup, but are on that one?

Sep 5, 2013 9:10 AM in response to Pondini

Pondini wrote:


Logical or not, it's a GREAT place to start. If you can replicate it, maybe I can; if I can, I can report it, and if AppleCare can replicate it, too, it'll go to the engineers.


No, I can't replicate it - i.e., there is no action or sequence of actions that I can perform that will cause it to happen. It happens when it happens, which is fairly regularly, at least once every 2 weeks on average.


What'll you bet they were excluded from the previous backup, but are on that one?


Engaging detective mode... The backup at 23:36 seems to be normal. The next backup at 00:36 gets interrupted by sleep:


Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: Will copy (9.7 MB) from Hard Disk

Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: Found 89 files (9.7 MB) needing backup

Sep 5 00:37:07 MBPro-11.local com.apple.backupd[60876]: 3.26 GB required (including padding), 9.24 GB available


That's the last log entry for backupd until I woke the system this morning:


Sep 5 09:27:07 MBPro-11.local com.apple.backupd[60876]: Backup failed because the network destination disk was ejected or disconnected unexpectedly!

Sep 5 09:27:07 MBPro-11.local com.apple.backupd[60876]: Copied 7.66 GB of 7.66 GB, 249347 of 249347 items

Sep 5 09:27:07 MBPro-11.local com.apple.backupd[60876]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error

(repeated several times)

Sep 5 09:27:07 MBPro-11.local com.apple.backupd[60876]: Copied 249347 files (7.66 GB) from volume Hard Disk.

Sep 5 09:27:07 MBPro-11.local com.apple.backupd[60876]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error

(repeated several times)

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Backup failed because the destination disk was ejected or disconnected unexpectedly!

Sep 5 09:27:09 MBPro-11.local com.apple.backupd[60876]: Backup canceled.


Note the bit in red - that probably means the 00:36 backup was already a mega-backup. It just got interrupted by system sleep and resumed this morning. I haven't done anything to generate that volume of changes on the drive. That points the finger at the 23:36 backup as being the one that excluded all the Applications, etc. directories. That backup process looks fine - no funny messages. However, install.log shows that installd did its thing at 23:37, just after the backup started.


Now it gets interesting - let's interleave the backupd log with the installd log:


Sep 4 23:36:11 MBPro-11.local com.apple.backupd[50346]: Starting automatic backup

Sep 4 23:36:11 MBPro-11.local com.apple.backupd[50346]: Attempting to mount network destination URL

Sep 4 23:36:11 MBPro-11.local com.apple.backupd[50346]: Mounted network destination at mount point:

Sep 4 23:37:00 MBPro-11.local installd[50521]: PackageKit: suspending backupd

Sep 4 23:37:00 MBPro-11.local install_monitor[50526]: Temporarily excluding: /Applications, /Library, /System, /bin, /private, /sbin, /usr

Sep 4 23:37:01 MBPro-11.local com.apple.backupd[50346]: Disk image mounted at: /Volumes/Time Machine Backups

Sep 4 23:37:01 MBPro-11.local com.apple.backupd[50346]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb

Sep 4 23:37:13 MBPro-11.local com.apple.backupd[50346]: Using file event preflight for Hard Disk

Sep 4 23:37:17 MBPro-11.local install_monitor[50526]: Re-included: /Applications, /Library, /System, /bin, /private, /sbin, /usr

Sep 4 23:37:17 MBPro-11.local installd[50521]: PackageKit: releasing backupd

Sep 4 23:37:20 MBPro-11.local com.apple.backupd[50346]: Will copy (43.8 MB) from Hard Disk

Sep 4 23:37:20 MBPro-11.local com.apple.backupd[50346]: Found 111 files (43.8 MB) needing backup

Sep 4 23:37:20 MBPro-11.local com.apple.backupd[50346]: 3.23 GB required (including padding), 9.24 GB available

Sep 4 23:54:47 MBPro-11.local com.apple.backupd[50346]: Copied 6926 files (76.8 MB) from volume Hard Disk.

Sep 4 23:54:52 MBPro-11.local com.apple.backupd[50346]: Using file event preflight for Hard Disk

Sep 4 23:54:53 MBPro-11.local com.apple.backupd[50346]: Will copy (34.6 MB) from Hard Disk

Sep 4 23:54:53 MBPro-11.local com.apple.backupd[50346]: Found 89 files (34.6 MB) needing backup

Sep 4 23:54:53 MBPro-11.local com.apple.backupd[50346]: 3.28 GB required (including padding), 9.24 GB available

Sep 4 23:56:54 MBPro-11.local com.apple.backupd[50346]: Copied 1899 files (84.6 MB) from volume Hard Disk.

Sep 4 23:56:59 MBPro-11.local com.apple.backupd[50346]: Created new backup: 2013-09-04-235657

Sep 4 23:57:14 MBPro-11.local com.apple.backupd[50346]: Starting post-backup thinning

Sep 4 23:57:14 MBPro-11.local com.apple.backupd[50346]: No post-back up thinning needed: no expired backups exist

Sep 4 23:57:14 MBPro-11.local com.apple.backupd[50346]: Backup completed successfully.


Now, wait a minute - installd SUSPENDS backupd at 23:37:00 and changes the .plist to exclude the directories with executables in them - but backupd carries on doing things AFTER that point. installd put the .plist back to normal and "releases" backupd at 23:37:17, but backupd hasn't been suspended at all.


Have I cracked it this time? Is the problem due to backupd ignoring the attempted suspension by installd and just carrying on, reading the .plist file while it is in the ExcludeByPath state? It's consistent with what the logs show, and with the activity by backupd thereafter.

Sep 5, 2013 10:40 AM in response to Ross Barkman

Ross Barkman wrote:

. . .

Now, wait a minute - installd SUSPENDS backupd at 23:37:00 and changes the .plist to exclude the directories with executables in them - but backupd carries on doing things AFTER that point. installd put the .plist back to normal and "releases" backupd at 23:37:17, but backupd hasn't been suspended at all.


Have I cracked it this time? Is the problem due to backupd ignoring the attempted suspension by installd and just carrying on, reading the .plist file while it is in the ExcludeByPath state? It's consistent with what the logs show, and with the activity by backupd thereafter.

There might be more in the hidden log and exclusion list TM keeps in every backup folder. They're less pretty, but more detailed. Bit of a pain to have to show hidden items, then grant yourself read permissions, but just might be worth a look.


Have at it, Sherlock! 👿

Sep 5, 2013 1:38 PM in response to Pondini

I think we've cracked it.


I used Kilometer as a quicker way to see the hidden files & change the permissions. The .exclusions.plist file for the problematic 23:36 backup doesn't list the Applications, etc. paths. There's a long list of standard exclusions (stuff like /tmp), and my user exclusions are listed, but no mention of the problematic paths. Same with the .exclusions.plist for the previous backup at 22:36. The .backup.log files are pretty useless, as they have no timestamps.


However, the Hard Disk folder in the 23:36 backup does not have Applications or the other problematic folders in it. The 22:36 backup does, and the mega-backup that finally completed at 12:26 today also does. In fact, all the recent backups contain the full disk structure (minus the standard exclusions and my user exclusions) except the 23:36 backup that appears to clash with installd.


I think that's pretty conclusve. installd tries to suspend backupd and then changes the .plist file to exclude /Applications, /Library, /System, /bin, /private, /sbin and /usr. But backupd keeps running, and reads the modified .plist file, which means it excludes all those paths from its backup. installd then changes the .plist back, so the next backup has to add all those files back again. The underlying problem is that backupd (or whatever process handles suspend requests) does not 'respect' the suspend request from installd


Now, as I discussed in my earlier post, the chances of installd and backupd tripping over each other are usually pretty remote. But with a regular background autoupdate process running on an hourly schedule, those chances increase significantly. There may be other things that drive the two processes into synchronisation - for example, Sophos's update check and Time Machine both kick off shortly after the system boots or wakes, so they tend to run at about the same time every hour. Eventually, they trip over each other.

Sep 5, 2013 2:18 PM in response to Ross Barkman

Ross Barkman wrote:


I think we've cracked it.

Yup -- one scenario, at least (I wouldn't rule out others . . .). 🙂


The underlying problem is that backupd (or whatever process handles suspend requests) does not 'respect' the suspend request from installd

Absolutely.


Now the big question: how do we get this to Apple?


I assume you don't have a Mac covered by AppleCare, so would have to pay $50 or $60 U.S. to get to them. You can certainly (and probably should) file a normal Bug Report, but those usually don't get high-priority attention.


I do, but am not sure I can trigger it at will. I do a lot of testing of TM, and have cancelled many backups with no problem. I can download an app that sets a fixed path exclusion (the demo of Drive Genius is one), and try cancelling backup after backup, but I'm a bit skeptical.


I stay as far away from anti-virus stuff as possible, too, but as the Sophos product seems to be relatively harmless, I could install it (cringe).


Thoughts?

Sep 5, 2013 4:11 PM in response to Pondini

Pondini wrote:


Yup -- one scenario, at least (I wouldn't rule out others . . .). 🙂


True - at least we can get this one looked at.


I assume you don't have a Mac covered by AppleCare


This MBPro is still covered - purchased 2011 with 3-year AppleCare (i.e. warranty + 2). Now that I have somethng concrete to report, I'll see how far I can take it.


I don't think it's worth looking too hard at third-party exclusions - my current .plist has none, and I still get mega-backups. I would hope that backupd is pretty well equipped to deal with cancelled & interrupted backups, though there might be an issue lurking somewhere.


My money is still on this clash between installd and backupd as the major source. There must be other apps out there like Sophos that do autoupdates; I think Google does (I see something called GoogleSoftwareUpdateAgent appear occasionally, though it never asks me to authorise an update), and then there's Apple's own limited AV system.

Sep 5, 2013 4:32 PM in response to Ross Barkman

Ross Barkman wrote:

. . .

I don't think it's worth looking too hard at third-party exclusions - my current .plist has none, and I still get mega-backups.

That's curious. Every case I've seen has had at least one other entry in ExcludeByPath, most with Microsoft PlayReady. But of course, many users had either lost their OSX drive or already run the fix, so the evidence was lost.



My money is still on this clash between installd and backupd as the major source. There must be other apps out there like Sophos that do autoupdates; I think Google does (I see something called GoogleSoftwareUpdateAgent appear occasionally, though it never asks me to authorise an update), and then there's Apple's own limited AV system.


You may well be right. Don't hesitate to refer them to my webpage at http://pondini.org/TM/D10.html, and encourage them to click the link at the bottom of the yellow box. I posted links to a number of threads there (including this one), as evidence this isn't an isolated occurrence.


I'd also be quite willing to send them affected plists from about a dozen users, including at least one TMdiagnostic package. And/or provide any other info I can.


I also know of three Bug Reports filed: 14066049, 14782487, and 14827513; plus one AppleCare Case Number 443758601, filed before the user knew the rest.


Keep me posted, and if you don't mind, send me the AppleCare case number.

Sep 5, 2013 5:05 PM in response to Ross Barkman

Ross Barkman wrote:

I don't think it's worth looking too hard at third-party exclusions - my current .plist has none, and I still get mega-backups. I would hope that backupd is pretty well equipped to deal with cancelled & interrupted backups, though there might be an issue lurking somewhere.


My money is still on this clash between installd and backupd as the major source. There must be other apps out there like Sophos that do autoupdates ...

For what very little it is worth, I have a number of third party exclusions in my plist & allow Sophos to run hourly downloads. I have never seen any signs of this bug on my iMac. No mega-backups; no missing system level folders from any TM backup.

UPDATED: Serious Time Machine bug on Mountain Lion

Welcome to Apple Support Community
A forum where Apple customers help each other with their products. Get started with your Apple Account.