Time Capsule backup consistently fails

backuphard drivetime-capsule

I am running El Capitan (10.11.3 beta) on a 2011 27" iMac. Recently, my Time Machine backups (I have a Time Capsule connected to the computer directly by USB) started to fail. First, I got a message to the effect that my backup's integrity could not be guaranteed, offering me to perform a new full backup (and lose the old ones). Here are the relevant lines in system.log:

12/28/15 11:24:49.549 PM com.apple.backupd[67878]: Error: (-43) SrcErr:NO Copying /Volumes/Data/Users/artemio/Library/Metadata/com.apple.IntelligentSuggestions/10656.vcf to /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-28-232339.inProgress/73292B5F-3A02-40BF-A572-8281FFC6A0DB/Data/Users/artemio/Library/Metadata/com.apple.IntelligentSuggestions
12/28/15 11:24:49.553 PM com.apple.backupd[67878]: Copy stage failed with error:11
*****
12/29/15 12:28:06.938 AM com.apple.backupd[67927]: Backing up to /dev/disk4s2: /Volumes/Time Machine Backups/Backups.backupdb
12/29/15 12:29:39.989 AM com.apple.backupd[67927]: Error: (5) getxattr for key:com.apple.backupd.SnapshotVolumeUUID path:/Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-28-222126/Macintosh HD
12/29/15 12:29:45.976 AM com.apple.backupd[67927]: Error: (5) getxattr for key:com.apple.backupd.SnapshotVolumeUUID path:/Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-28-222126/Macintosh HD
12/29/15 12:29:54.077 AM com.apple.backupd[67927]: Error: (5) getxattr for key:com.apple.backupd.SnapshotVolumeUUID path:/Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-28-222126/Macintosh HD
12/29/15 12:29:54.803 AM com.apple.backupd[67927]: Forcing deep traversal on source: "Macintosh HD" (device: /dev/disk0s2 mount: '/' fsUUID: D27A3D7F-3691-362B-9673-99E35AFD7133 eventDBUUID: B1BBE4B9-1158-4766-9A3A-4A3B2AA8B66A)
12/29/15 12:33:32.613 AM com.apple.backupd[67927]: Will copy (21.3 MB) from Data
12/29/15 12:33:32.615 AM com.apple.backupd[67927]: Deep event scan at path:/ reason:must scan subdirs|require scan|
12/29/15 12:33:32.615 AM com.apple.backupd[67927]: Running event scan
12/29/15 12:33:32.615 AM com.apple.backupd[67927]: Finished scan
12/29/15 12:33:32.817 AM com.apple.backupd[67927]: Saved event cache at /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-29-002946.inProgress/36B5F3C4-A7C4-4868-BE96-27C449C92326/.D27A3D7F-3691-362B-9673-99E35AFD7133.eventdb
12/29/15 12:33:32.817 AM com.apple.backupd[67927]: Not using file event preflight for Macintosh HD
12/29/15 12:38:04.429 AM com.apple.backupd[67927]: Will copy (27.12 GB) from Macintosh HD
12/29/15 12:38:09.602 AM com.apple.backupd[67927]: Found 547502 files (27.14 GB) needing backup
12/29/15 12:40:03.201 AM com.apple.backupd[67927]: 38.35 GB required (including padding), 829.8 GB available
12/29/15 12:42:44.047 AM com.apple.backupd[67927]: Error: (-36) SrcErr:NO Copying /Volumes/Data/Users/artemio/.dropbox/finderplugin/l to /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-29-002946.inProgress/36B5F3C4-A7C4-4868-BE96-27C449C92326/Data/Users/artemio/.dropbox/finderplugin
12/29/15 12:43:02.736 AM com.apple.backupd[67927]: Error: (-36) SrcErr:NO Copying /Volumes/Data/Users/artemio/.dropbox/finderplugin to /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-29-002946.inProgress/36B5F3C4-A7C4-4868-BE96-27C449C92326/Data/Users/artemio/.dropbox
12/29/15 12:48:28.281 AM com.apple.backupd[67927]: Error: (-36) SrcErr:NO Copying /Volumes/Data/Users/artemio/.dropbox/instance1 to /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-29-002946.inProgress/36B5F3C4-A7C4-4868-BE96-27C449C92326/Data/Users/artemio/.dropbox
12/29/15 12:48:52.539 AM com.apple.backupd[67927]: Stopping backup.
12/29/15 12:48:52.539 AM com.apple.backupd[67927]: Error: (-43) SrcErr:NO Copying /Volumes/Data/Users/artemio/.emacs-save to /Volumes/Time Machine Backups/Backups.backupdb/iMac 27/2015-12-29-002946.inProgress/36B5F3C4-A7C4-4868-BE96-27C449C92326/Data/Users/artemio
12/29/15 12:48:52.561 AM com.apple.backupd[67927]: Stopping backup to allow backup destination disk to be unmounted or ejected.
12/29/15 12:48:52.568 AM com.apple.backupd[67927]: Copied 10 items (Zero KB) from volume Data. Linked 70.
12/29/15 12:48:52.572 AM com.apple.backupd[67927]: Copy stage failed with error:11
*****
12/29/15 1:49:44.818 AM com.apple.backupd[68082]: Runtime corruption detected on /Volumes/ATC/iMac 27.sparsebundle (fsck_hfs -q termination status: 3)

I answered "yes" to the request to create a new backup, but this failed after a while:

12/29/15 7:04:49.652 PM com.apple.backupd[68082]: Recovery backup requested by user.
12/29/15 7:18:54.648 PM com.apple.backupd[68082]: Deleted backup image: /Volumes/ATC/iMac 27.purgeable.  1.39 TB available on host volume.
12/29/15 7:18:55.058 PM com.apple.backupd[68082]: Creating disk image /Volumes/ATC/iMac 27.sparsebundle
12/29/15 7:20:00.933 PM com.apple.backupd[68082]: setting security information: Operation not permitted
12/29/15 7:20:01.147 PM com.apple.backupd[68082]: setting security information: Operation not permitted
12/29/15 7:20:03.490 PM com.apple.backupd[68082]: Checking for runtime corruption on /dev/disk4s2
12/29/15 7:20:10.285 PM com.apple.backupd[68082]: Disk image /Volumes/ATC/iMac 27.sparsebundle mounted at: /Volumes/Time Machine Backups
12/29/15 7:20:10.291 PM com.apple.backupd[68082]: Network destination already mounted at: /Volumes/ATC
12/29/15 7:20:11.734 PM com.apple.backupd[68082]: Disk image already attached: /Volumes/ATC/iMac 27.sparsebundle, DIHLDiskImageAttach returned: 35 (Resource temporarily unavailable)
12/29/15 7:20:11.936 PM com.apple.backupd[68082]: Backing up to /dev/disk5s2: /Volumes/Time Machine Backups/Backups.backupdb
12/29/15 7:20:11.936 PM com.apple.backupd[68082]: Ownership is disabled on the backup destination volume.  Enabling.
12/29/15 7:20:12.993 PM com.apple.backupd[68082]: Disk image /Volumes/ATC/iMac 27.sparsebundle mounted at: /Volumes/Time Machine Backups
12/29/15 7:20:14.331 PM com.apple.backupd[68082]: Forcing deep traversal on source: "Data" (device: /dev/disk1s2 mount: '/Volumes/Data' fsUUID: A6AA037F-C9AA-3243-BCF1-203646ABFBBA eventDBUUID: 30106177-2CA1-4B99-AAB3-52D5563ADA53)
12/29/15 7:20:14.331 PM com.apple.backupd[68082]: Forcing deep traversal on source: "Macintosh HD" (device: /dev/disk0s2 mount: '/' fsUUID: D27A3D7F-3691-362B-9673-99E35AFD7133 eventDBUUID: B1BBE4B9-1158-4766-9A3A-4A3B2AA8B66A)
12/29/15 7:21:29.880 PM com.apple.backupd[68082]: Total content size: 407.4 GB excluded items size: 88.65 GB for volume Data
12/29/15 7:21:42.225 PM com.apple.backupd[68082]: Total content size: 115.53 GB excluded items size: 22.43 GB for volume Macintosh HD
12/29/15 7:21:42.225 PM com.apple.backupd[68082]: Found 4608536 files (411.84 GB) needing backup
12/29/15 7:21:42.225 PM com.apple.backupd[68082]: 433.32 GB required (including padding), 1.39 TB available
12/29/15 7:21:42.249 PM com.apple.backupd[68082]: Waiting for index to be ready (100)
12/29/15 8:07:51.089 PM com.apple.backupd[68082]: Stopping backup to allow backup destination disk to be unmounted or ejected.
12/29/15 8:07:51.693 PM com.apple.backupd[68082]: Copied 172989 items (48.18 GB) from volume Data. Linked 0.
12/29/15 8:07:51.722 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.723 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.723 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.723 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.725 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.725 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:07:51.726 PM com.apple.backupd[68082]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error
12/29/15 8:08:01.286 PM com.apple.backupd[68082]: Cancellation timed out - exiting

After that, I erased the old backup dmg file, unmounted the Time Capsule disk and tried to create a new backup manually several times. This always fails after a while, with an error message similar to this:

12/29/15 10:20:28.091 PM com.apple.backupd[69761]: Error writing to backup log.  NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Input/output error

There are also repeated warnings similar to the following:

12/29/15 11:21:17.243 PM com.apple.backupd[70000]: Checking for runtime corruption on /dev/disk2s2

All of this seems to me to point to hard drive failure. Another fact supporting this conclusion is that I have been able to backup to a USB external disk. On the other hand, 1) I have restarted the Time Capsule (which is supposed to fsck the hard drive) without any errors detected, and 2) another computer of mine is backing up wirelessly to this Time Capsule without problems so far (although, truth be told, I do get "checking for runtime corruption on /dev/disks…" messages in the backup log). So my questions are:

1) How could I test if my problem is due to hard disk corruption?
2) If the answer is "yes", is it simple to replace the hard drive inside the Time Capsule?
3) If you think that the problem may be software related, what are your suggestions for troubleshooting/fixing it?

Best Answer

When I had this problem I found it was due to permissions conflicts. Time machine worked after I repaired permissions but not using diskutil for the repair.