How can I avoid repeated "Time Machine must create a new backup" errors when backing up to a third party NAS?
Suitability of HFS Plus
Whilst Time Machine must use HFS Plus for most things, it's worth noting that the file system is not ideally suited for the task.
An example
Coincidence: a few hours after my first edition of this answer, my own Time Machine Backups volume (a sparse bundle disk image) suffered a file system failure. I'm certain that the underlying storage is OK – a ZFS pool scrubbed, without error, before and after the HFS Plus failure. For the record:
2013-06-07 18:02:54.332 com.apple.backupd[18433] Starting automatic backup
2013-06-07 18:02:56.292 com.apple.backupd[18433] Resizing backup disk image from 2.65 TB to 2.6 TB
2013-06-07 18:03:34.119 com.apple.backupd[18433] Disk image /Volumes/tall/com.apple.backupd/GPES3E-gjp4-1.sparsebundle mounted at: /Volumes/Time Machine Backups
2013-06-07 18:03:35.244 com.apple.backupd[18433] Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
2013-06-07 18:03:44.013 com.apple.backupd[18433] Inherited root volume OS, UUID: C5C41F95-133B-3EB0-9013-F94DAAA0D99B
2013-06-07 18:03:44.147 com.apple.backupd[18433] Forcing deep traversal on source: "OS" (mount: '/' fsUUID: 03AF4C8A-66E8-3DE2-B30F-176C0C2337C3 eventDBUUID: BDCB9532-A4A8-4B94-A6C1-928FD741B07A)
2013-06-07 18:03:44.148 com.apple.backupd[18433] Event store UUIDs don't match for volume: spare
2013-06-07 18:03:44.150 com.apple.backupd[18433] Event store UUIDs don't match for volume: disk0s3
2013-06-07 18:03:47.612 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-103948 does not contain spare. Skipping it.
2013-06-07 18:03:47.663 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215311 does not contain spare. Skipping it.
2013-06-07 18:03:47.714 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-075155 does not contain spare. Skipping it.
2013-06-07 18:03:47.764 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-055748 does not contain spare. Skipping it.
2013-06-07 18:03:47.827 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-220121 does not contain spare. Skipping it.
2013-06-07 18:03:47.888 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-081211 does not contain spare. Skipping it.
2013-06-07 18:03:47.966 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215312 does not contain spare. Skipping it.
2013-06-07 18:03:48.025 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-235752 does not contain spare. Skipping it.
2013-06-07 18:03:48.087 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-140311 does not contain spare. Skipping it.
2013-06-07 18:03:48.145 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215718 does not contain spare. Skipping it.
2013-06-07 18:03:48.202 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-005749 does not contain spare. Skipping it.
2013-06-07 18:03:48.261 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-235753 does not contain spare. Skipping it.
2013-06-07 18:03:48.321 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-160310 does not contain spare. Skipping it.
2013-06-07 18:03:48.558 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-074020 does not contain spare. Skipping it.
2013-06-07 18:03:48.619 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-025748 does not contain spare. Skipping it.
2013-06-07 18:03:48.709 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-015751 does not contain spare. Skipping it.
2013-06-07 18:03:48.904 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-025749 does not contain spare. Skipping it.
2013-06-07 18:03:48.954 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-015752 does not contain spare. Skipping it.
2013-06-07 18:03:49.004 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-130310 does not contain spare. Skipping it.
2013-06-07 18:03:49.055 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-045748 does not contain spare. Skipping it.
2013-06-07 18:03:49.162 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215950 does not contain spare. Skipping it.
2013-06-07 18:03:49.211 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-092036 does not contain spare. Skipping it.
2013-06-07 18:03:49.273 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-035751 does not contain spare. Skipping it.
2013-06-07 18:03:49.321 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-225752 does not contain spare. Skipping it.
2013-06-07 18:03:49.371 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-065747 does not contain spare. Skipping it.
2013-06-07 18:03:49.420 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-045749 does not contain spare. Skipping it.
2013-06-07 18:03:49.470 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-213710 does not contain spare. Skipping it.
2013-06-07 18:03:49.519 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-091305 does not contain spare. Skipping it.
2013-06-07 18:03:49.589 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-150310 does not contain spare. Skipping it.
2013-06-07 18:03:49.639 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-065748 does not contain spare. Skipping it.
2013-06-07 18:03:49.688 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-074521 does not contain spare. Skipping it.
2013-06-07 18:03:49.776 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-220105 does not contain spare. Skipping it.
2013-06-07 18:03:49.838 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-225749 does not contain spare. Skipping it.
2013-06-07 18:03:49.899 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-092118 does not contain spare. Skipping it.
2013-06-07 18:03:50.119 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-120311 does not contain spare. Skipping it.
2013-06-07 18:03:50.388 com.apple.backupd[18433] Mobile backup /Volumes/MobileBackups/Backups.backupdb/GPES3E-gjp4-1/2013-06-07-035749 does not contain spare. Skipping it.
2013-06-07 18:03:51.141 com.apple.backupd[18433] Deep event scan at path:/ reason:must scan subdirs|require scan|
2013-06-07 18:03:51.141 com.apple.backupd[18433] Finished scan
2013-06-07 18:16:29.077 com.apple.backupd[18433] Deep event scan at path:/Volumes/spare reason:must scan subdirs|new event db|
2013-06-07 18:16:29.086 com.apple.backupd[18433] Finished scan
2013-06-07 18:16:29.570 com.apple.backupd[18433] Deep event scan at path:/Volumes/disk0s3 reason:must scan subdirs|new event db|
2013-06-07 18:16:29.786 com.apple.backupd[18433] Finished scan
2013-06-07 18:16:30.310 com.apple.backupd[18433] Found 1695685 files (84.93 GB) needing backup
2013-06-07 18:16:31.053 com.apple.backupd[18433] 109.44 GB required (including padding), 2 TB available
2013-06-07 18:54:10.918 com.apple.backupd[18433] Unexpected result from MDBackupIndexFile (1) for: /Applications/Freenet/datastore/CHK-cache.hd, /Volumes/Time Machine Backups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215332.inProgress/9086512E-E386-475E-AE99-34BAA1D2E485/OS/Applications/Freenet/datastore/CHK-cache.hd
2013-06-07 18:54:24.848 com.apple.backupd[18433] Unexpected result from MDBackupIndexFile (1) for: /Applications/Freenet/datastore/CHK-store.hd, /Volumes/Time Machine Backups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215332.inProgress/9086512E-E386-475E-AE99-34BAA1D2E485/OS/Applications/Freenet/datastore/CHK-store.hd
2013-06-07 19:03:44.609 com.apple.backupd[18433] Copied 18.81 GB of 84.93 GB, 460244 of 1695685 items
2013-06-07 20:03:44.827 com.apple.backupd[18433] Copied 34.12 GB of 84.93 GB, 815234 of 1695685 items
2013-06-07 21:03:54.004 com.apple.backupd[18433] Copied 40.73 GB of 84.93 GB, 1013214 of 1695685 items
2013-06-07 22:03:54.678 com.apple.backupd[18433] Copied 67.55 GB of 84.93 GB, 1508426 of 1695685 items
2013-06-07 22:28:43.226 com.apple.backupd[18433] Copied 1786731 files (77.59 GB) from volume OS.
2013-06-07 22:28:49.157 com.apple.backupd[18433] Unexpected result from MDBackupIndexFile (1) for: /Volumes/spare/Tocar y Luchar JAA.cdr, /Volumes/Time Machine Backups/Backups.backupdb/GPES3E-gjp4-1/2013-06-06-215332.inProgress/9086512E-E386-475E-AE99-34BAA1D2E485/spare/Tocar y Luchar JAA.cdr
2013-06-07 22:28:51.508 com.apple.backupd[18433] Error: Flushing index to disk returned an error: 1
2013-06-07 22:28:51.508 com.apple.backupd[18433] Copied 1786746 files (77.59 GB) from volume spare.
2013-06-07 22:29:11.108 com.apple.backupd[18433] Backup canceled.
2013-06-07 22:29:23.227 com.apple.backupd[18433] Ejected Time Machine disk image: /Volumes/tall/com.apple.backupd/GPES3E-gjp4-1.sparsebundle
2013-06-07 23:10:44.791 com.apple.backupd[28884] Starting automatic backup
2013-06-07 23:10:45.269 com.apple.backupd[28884] Backup failed with error: 1002
2013-06-07 23:10:45.382 com.apple.backupd[28884] Starting automatic backup
2013-06-07 23:10:46.446 com.apple.backupd[28884] Resizing backup disk image from 2.6 TB to 2.6 TB
2013-06-07 23:10:50.162 com.apple.backupd[28884] Runtime corruption detected on /Volumes/tall/com.apple.backupd/GPES3E-gjp4-1.sparsebundle (fsck_hfs -q termination status: 3)
the message at 2013-06-07 22:28:49 is eye-catching, but expected in my case (symptom of a bug involving HFS Plus; a corruption that involves AppleFSCompression) – probably negligible in the context of this answer
the message at 2013-06-07 22:28:51 may be more relevant to the file system failure.
/private/var/log/fsck_hfs.log
then showed:
/dev/rdisk7s2: fsck_hfs run at Fri Jun 7 23:10:48 2013
/dev/rdisk7s2: ** /dev/rdisk7s2 (NO WRITE)
/dev/rdisk7s2: Executing fsck_hfs (version diskdev_cmds-557.3.1~5).
QUICKCHECK ONLY; FILESYSTEM DIRTY
/dev/rdisk7s2: fsck_hfs run at Fri Jun 7 23:10:49 2013
/dev/rdisk7s2: ** /dev/rdisk7s2 (NO WRITE)
/dev/rdisk7s2: Executing fsck_hfs (version diskdev_cmds-557.3.1~5).
QUICKCHECK ONLY; FILESYSTEM DIRTY
Confirming that no error affected the underlying storage at the time:
GPES3E-gjp4-1:~ gjp22$ date
Sat 8 Jun 2013 06:57:46 BST
GPES3E-gjp4-1:~ gjp22$ uptime
6:57 up 21:51, 5 users, load averages: 0.92 1.27 1.37
GPES3E-gjp4-1:~ gjp22$ zpool status
pool: gjp22
state: ONLINE
scan: scrub repaired 0 in 24h8m with 0 errors on Sat May 25 23:25:38 2013
config:
NAME STATE READ WRITE CKSUM
gjp22 ONLINE 0 0 0
GPTE_71B8BDA2-3EBA-4B91-9E1C-2AE2B1DAAD06 ONLINE 0 0 0 at disk3s2
cache
GPTE_2605CCB0-67B7-4C93-A4B1-83EF764CE617 OFFLINE 1.48Ki 0
errors: No known data errors
pool: tall
state: ONLINE
scan: scrub repaired 0 in 28h10m with 0 errors on Sun May 26 18:47:22 2013
config:
NAME STATE READ WRITE CKSUM
tall ONLINE 0 0 0
GPTE_78301A52-4AFF-4D96-8DE9-E76ABC14909C ONLINE 0 0 0 at disk2s2
GPTE_99056308-F5E2-4314-852C-4DA04732A2D0 ONLINE 0 0 0 at disk6s2
errors: No known data errors
GPES3E-gjp4-1:~ gjp22$
In simple terms
Whilst we'd like a solution, file system failures such as this seem to be:
- unpredictable
- unavoidable
- sometimes irreparable.
In the absence of a good solution, my best advice is to not rely on a single Time Machine backup. The risk of eventual failure and inability to repair is simply too high.
Degrees of failure
In the past I sometimes forced fsck_hfs
(8) to rebuild b-tree files … with limited success but not certainty. Whilst a file system may appear to be OK (in Disk Utility and the like) I would not no longer trust it for Time Machine backup or restoration purposes.
In the most recent case (above) multiple applications of force (multiple rebuilds of the catalog b-tree, a rebuild of the extended attributes b-tree and a rebuild of the extents b-tree) have not led to a verifiable file system. I have debug logs from these attempts, which I'll not begin to summarise here; they're massive.
With locally attached disks (USB 2.0), attempts to repair Time Machine backup volumes can be extraordinarily time consuming. Wireless – over AFP – you may find the time required intolerable.
Time Machine - Troubleshooting – C13. "…Time Machine must create a new backup for you." (James Pond) includes much useful information. Essentially:
… backups are corrupted beyond Disk Utility's ability to fix …
When OS X reports that an HFS Plus file system appears to be OK, there may be significant issues with the disk – issues that OS X simply can not detect.
As corruption has occurred more than once, there may be a problem with:
- hardware, firmware and/or software of the NAS.
What make and model is the NAS?
Hard disks of the NAS
If the OS of the NAS allows you to verify integrity of blocks on its disks: please do so.
If the OS of the NAS lacks that capability, then aim to boot the hardware with a different OS that's more suitable for testing. Options might include Ubuntu and a run of badblocks.
Checks of this type:
- will be time consuming; but
- should help you to determine whether the state of the disk(s) is contributory to the multiple failures.
To add to @GrahamPerrin ’s warning, I want to share my plan for that.
My NAS is running FreeNAS which features ZFS.
Aware of the “Time Machine must create a new backup” issue before setting things up, I made the TimeMachine host volume on the NAS a separate ZFS Volume, used only for that. Then I specified daily volume snapshots. If the contents of the ZPool1/Backups/TimeMachine
volume get corrupted due to network snafu or the general unreliability of HFS+ virtual disk inside another volume, I can roll it back on the NAS. I sometimes call this the meta backup.
To be clear,
- the Host Volume is the NAS storage
ZPool1/Backups/TimeMachine
- it contains a HFS+ virtual disk, as host's directory
"John's MacBook Pro.sparsebundle"
which itself has abands
subdirectory containing the fully-provisioned virtual drive storage as 951 files with names likee8
(hex numbers counting up from 0). - The virtual disk is how Time Machine automatically handles a target volume that’s not HFS+. But I created it ahead of time to make chunk sizes efficient (128M each file).
- the NAS publishes
ZPool1/Backups/TimeMachine
as an AFP share with the “use for Time Machine” flag set. TimeMachine expects that to contain the virtual disk which it then uses, or creates if it’s the first use of that network location for backing up.
So, the ZFS volume snapshot capability works because it’s a ZFS volume containing a bunch of 128MB data files with boring names. Time Machine works because it puts a virtual disk formatted as HFS+ on whatever file system was presented.