NETGEAR is aware of a growing number of phone and online scams. To learn how to stay safe click here.
Forum Discussion
Debugging the Time Machine failures
I've gotten tired of the reoccurring "Time Machine completed a verification of your backups. To improve reliability, Time Machine must create a new backup for you.". Initially, I'd just let it run off and do it's thing to make a new one, but more recently I've wanted to figure out where the failure is. Today, the issue appeared, and here's what occurred.
I have a retina MacBook Pro, running 10.8.2, and attached to a Thunderbolt monitor. The system connects to my network via a wired connection to the monitor, or wireless when it's not connected. The backup device is an Duo v2 running 5.3.7. The tricky issue is that multiple vendors are involved, and it's easy to point fingers. I'm tempted to buy a Time Capsule and add it as a second destination just to be able to file bugs with Apple if the same issue occurs there.
Today, I undocked the laptop while running, and had noted the Time Machine icon animating right about the time I pulled the plug.
Below are the interesting logs around the time. I tried to include relevant kernel logs to detail the AFP reconnects, as well as the Thunderbolt connection breaking. One random theory, the ReadyNAS AFP implementation didn't quite have time to flush data properly from the connection loss before the Mac was already reconnecting.
I was hoping to cross reference my Mac logs with ReadyNAS logs, but afp.log appears to not have much in it past November 16th, when I believe I updated to 5.3.7. Did verbosity get turned nearly off for netafp?
Later on the 5th is when the system tried to backup again, and displayed the dreaded dialog. I followed along with the steps at http://www.garth.org/archives/2011,08,2 ... rrors.html to try and fix the problem. And when running fsck, I got this nice dump indicating repair is not possible. A second run resulted in identical output.
Perhaps with more detailed reports when this issue happens, the bugs can be fixed down the road. Unfortunately Apple is unlikely to be receptive with the ReadyNAS in the mix, but I'm going to attempt to file a bug with them and see where it goes.
I have a retina MacBook Pro, running 10.8.2, and attached to a Thunderbolt monitor. The system connects to my network via a wired connection to the monitor, or wireless when it's not connected. The backup device is an Duo v2 running 5.3.7. The tricky issue is that multiple vendors are involved, and it's easy to point fingers. I'm tempted to buy a Time Capsule and add it as a second destination just to be able to file bugs with Apple if the same issue occurs there.
Today, I undocked the laptop while running, and had noted the Time Machine icon animating right about the time I pulled the plug.
Below are the interesting logs around the time. I tried to include relevant kernel logs to detail the AFP reconnects, as well as the Thunderbolt connection breaking. One random theory, the ReadyNAS AFP implementation didn't quite have time to flush data properly from the connection loss before the Mac was already reconnecting.
I was hoping to cross reference my Mac logs with ReadyNAS logs, but afp.log appears to not have much in it past November 16th, when I believe I updated to 5.3.7. Did verbosity get turned nearly off for netafp?
12/5/12 2:06:51.158 PM com.apple.backupd[40822]: Starting automatic backup
12/5/12 2:06:51.185 PM com.apple.backupd[40822]: Attempting to mount network destination URL: afp://[email protected]/ReadyNAS
12/5/12 2:06:57.891 PM com.apple.backupd[40822]: Mounted network destination at mount point: /Volumes/ReadyNAS using URL: afp://[email protected]/ReadyNAS
12/5/12 2:08:19.894 PM com.apple.backupd[40822]: Disk image /Volumes/ReadyNAS/Ladon.sparsebundle mounted at: /Volumes/Time Machine Backups
12/5/12 2:08:19.897 PM com.apple.backupd[40822]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
12/5/12 2:08:32.231 PM com.apple.backupd[40822]: Using file event preflight for OS X
12/5/12 2:08:38.825 PM com.apple.backupd[40822]: Will copy (7.7 MB) from OS X
12/5/12 2:08:38.827 PM com.apple.backupd[40822]: Found 83 files (7.7 MB) needing backup
12/5/12 2:08:38.837 PM com.apple.backupd[40822]: 1.19 GB required (including padding), 537.37 GB available
12/5/12 2:12:44.493 PM com.apple.backupd[40822]: Copied 1186 files (20.8 MB) from volume OS X.
12/5/12 2:12:44.565 PM com.apple.backupd[40822]: Using file event preflight for OS X
12/5/12 2:12:46.974 PM com.apple.backupd[40822]: Will copy (384.2 MB) from OS X
12/5/12 2:12:46.977 PM com.apple.backupd[40822]: Found 114 files (384.2 MB) needing backup
12/5/12 2:12:46.977 PM com.apple.backupd[40822]: 1.64 GB required (including padding), 536.87 GB available
12/5/12 2:14:11.000 PM kernel[0]: [ PCI configuration begin ]
12/5/12 2:14:11.000 PM kernel[0]: PCI configuration changed (bridge=533 device=25 cardbus=0)
12/5/12 2:14:11.000 PM kernel[0]: [ PCI configuration end, bridges 12 devices 21 ]
12/5/12 2:14:11.000 PM kernel[0]: Ethernet [AppleBCM5701Ethernet]: Link down on en3 (offline)
12/5/12 2:14:11.000 PM kernel[0]: ASP_TCP Disconnect: triggering reconnect by bumping reconnTrigger from curr value 0 on so 0xffffff80509b7940
12/5/12 2:14:11.000 PM kernel[0]: ASP_TCP asp_tcp_usr_control: invalid kernelUseCount 0
12/5/12 2:14:11.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/ReadyNAS prevTrigger 0 currTrigger 1
12/5/12 2:14:11.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/ReadyNAS
12/5/12 2:14:11.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: soft mounted and hidden volume so do not notify KEA for /Volumes/ReadyNAS
12/5/12 2:14:11.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/ReadyNAS
12/5/12 2:14:11.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:14:11.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:14:12.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Logging in with uam 8 /Volumes/ReadyNAS
12/5/12 2:14:13.000 PM kernel[0]: ASP_TCP FindDSIReqInfo: in reconnect, but reconn reqInfo not in use 0x0 on 0xffffff80509b7940?
12/5/12 2:14:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/ReadyNAS
12/5/12 2:14:13.000 PM kernel[0]: ASP_TCP ReplayPendingReqs: replaying slot 61 with reqID 30879 afpCmd 0x3C on so 0xffffff80509b7940
12/5/12 2:14:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: get the reconnect token
12/5/12 2:14:13.000 PM kernel[0]: hfs_swap_BTNode: invalid forward link (0x261d396f >= 0x00012600)
12/5/12 2:14:13.000 PM kernel[0]: hfs: node=30372 fileID=4 volume=Time Machine Backups device=/dev/disk3s2
12/5/12 2:14:13.000 PM kernel[0]: hfs: Runtime corruption detected on Time Machine Backups, fsck will be forced on next mount.
12/5/12 2:14:13.177 PM com.apple.backupd[40822]: Stopping backup.
12/5/12 2:14:13.177 PM com.apple.backupd[40822]: Error: (-43) SrcErr:NO Copying /Users/drakino/Music/iTunes/iTunes Media/Music/Haito & Diringer to /Volumes/Time Machine Backups/Backups.backupdb/Ladon/2012-12-05-140832.inProgress/F313BD0E-3C11-46B7-8FAF-2424FC1EE346/OS X/Users/drakino/Music/iTunes/iTunes Media/Music
12/5/12 2:14:13.181 PM com.apple.backupd[40822]: Copied 895 files (156.2 MB) from volume OS X.
12/5/12 2:14:13.181 PM com.apple.backupd[40822]: Copy stage failed with error:11
12/5/12 2:14:37.224 PM com.apple.backupd[40822]: Backup failed with error: 11
12/5/12 2:14:37.000 PM kernel[0]: AirPort_Brcm43xx::powerChange: System Sleep
12/5/12 2:16:13.000 PM kernel[0]: Wake reason: EC.ACDetach (Maintenance)
12/5/12 2:16:13.000 PM kernel[0]: AirPort_Brcm43xx::powerChange: System Wake - Full Wake/ Dark Wake / Maintenance wake
12/5/12 2:16:13.000 PM kernel[0]: ASP_TCP Disconnect: triggering reconnect by bumping reconnTrigger from curr value 1 on so 0xffffff80509b7940
12/5/12 2:16:13.000 PM kernel[0]: ASP_TCP asp_tcp_usr_control: invalid kernelUseCount 0
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/ReadyNAS prevTrigger 1 currTrigger 2
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/ReadyNAS
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: soft mounted and hidden volume so do not notify KEA for /Volumes/ReadyNAS
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/ReadyNAS
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:16:13.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect on /Volumes/ReadyNAS failed 65.
12/5/12 2:16:13.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
12/5/12 2:16:14.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:16:14.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:16:14.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect on /Volumes/ReadyNAS failed 65.
12/5/12 2:16:14.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
12/5/12 2:16:15.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:16:15.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:16:15.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect on /Volumes/ReadyNAS failed 65.
12/5/12 2:16:15.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
12/5/12 2:16:16.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:16:16.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:16:16.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect on /Volumes/ReadyNAS failed 65.
12/5/12 2:16:16.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
12/5/12 2:16:17.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/ReadyNAS
12/5/12 2:16:17.000 PM kernel[0]: ASP_TCP asp_SetTCPQoS: sock_settclassopt got error 57
12/5/12 2:16:17.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Logging in with uam 8 /Volumes/ReadyNAS
12/5/12 2:16:17.000 PM kernel[0]: ASP_TCP FindDSIReqInfo: in reconnect, but reconn reqInfo not in use 0x0 on 0xffffff80509b7940?
12/5/12 2:16:19.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/ReadyNAS
12/5/12 2:16:19.000 PM kernel[0]: ASP_TCP ReplayPendingReqs: replaying slot 61 with reqID 31653 afpCmd 0xB on so 0xffffff80509b7940
12/5/12 2:16:19.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: get the reconnect token
12/5/12 2:16:40.000 PM kernel[0]: DarkWake thermal limits breached. Going to sleep!
12/5/12 2:16:47.000 PM kernel[0]: AFP_VFS afpfs_unmount: /Volumes/ReadyNAS, flags 0, pid 40913
12/5/12 2:16:47.000 PM kernel[0]: AFP_VFS afpfs_unmount : We are the last mnt/sbmnt using volume /Volumes/ReadyNAS 0xffffff81a7b98008
12/5/12 2:16:47.000 PM kernel[0]: ASP_TCP do_thread_read: no reqInfo found for reqID 0
12/5/12 2:16:47.000 PM kernel[0]: AFP_VFS afpfs_unmount : We are the last volume using socket /Volumes/ReadyNAS 0xffffff81a7b98008
12/5/12 2:16:47.000 PM kernel[0]: AFP_VFS afpfs_unmount : afpfs_DoReconnect sent signal for unmount to proceed
12/5/12 2:16:47.000 PM kernel[0]: AirPort_Brcm43xx::powerChange: System Sleep
12/5/12 2:16:47.260 PM com.apple.backupd[40822]: Ejected Time Machine disk image: /Volumes/ReadyNAS/Ladon.sparsebundle
12/5/12 2:16:47.696 PM com.apple.backupd[40822]: Ejected Time Machine network volume.
Later on the 5th is when the system tried to backup again, and displayed the dreaded dialog. I followed along with the steps at http://www.garth.org/archives/2011,08,2 ... rrors.html to try and fix the problem. And when running fsck, I got this nice dump indicating repair is not possible. A second run resulted in identical output.
fsck_hfs -drfy /dev/disk2s2
journal_replay(/dev/disk2s2) returned 0
** /dev/rdisk2s2
Using cacheBlockSize=32K cacheTotalBlock=65536 cacheSize=2097152K.
Executing fsck_hfs (version diskdev_cmds-557~393).
** Checking Journaled HFS Plus volume.
** Detected a case-sensitive volume.
The volume name is Time Machine Backups
** Checking extents overflow file.
** Checking catalog file.
** Rebuilding catalog B-tree.
Extent records for rebuilt file 4:
[ 274597, 150528 ]
[ 0, 0 ]
[ 0, 0 ]
[ 0, 0 ]
[ 0, 0 ]
[ 0, 0 ]
[ 0, 0 ]
[ 0, 0 ]
hfs_UNswap_BTNode: invalid node height (1)
btree file 4: 1000 records
btree file 4: 2000 records
btree file 4: 3000 records
btree file 4: 4000 records
btree file 4: 5000 records
btree file 4: 6000 records
btree file 4: 7000 records
btree file 4: 8000 records
btree file 4: 9000 records
btree file 4: 10000 records
btree file 4: 11000 records
btree file 4: 12000 records
btree file 4: 13000 records
btree file 4: 14000 records
btree file 4: 15000 records
btree file 4: 16000 records
btree file 4: 17000 records
btree file 4: 18000 records
btree file 4: 19000 records
btree file 4: 20000 records
btree file 4: 21000 records
btree file 4: 22000 records
btree file 4: 23000 records
btree file 4: 24000 records
btree file 4: 25000 records
btree file 4: 26000 records
btree file 4: 27000 records
btree file 4: 28000 records
btree file 4: 29000 records
btree file 4: 30000 records
btree file 4: 31000 records
btree file 4: 32000 records
btree file 4: 33000 records
btree file 4: 34000 records
btree file 4: 35000 records
btree file 4: 36000 records
btree file 4: 37000 records
btree file 4: 38000 records
btree file 4: 39000 records
btree file 4: 40000 records
btree file 4: 41000 records
btree file 4: 42000 records
btree file 4: 43000 records
RebuildBTree - InsertBTreeRecord failed with err 5 0x05
RebuildBTree - numRecords = 43221
RebuildBTree - record 22 in node 970 is not recoverable.
xxxxxxxx BTreeKey (length 14) xxxxxxxx
0C 00 FC 54 00 00 03 00 4D 00 49 00 4F 00 ...T....M.I.O.
xxxxxxxx BTreeData (length 248) xxxxxxxx
02 00 0E 00 00 00 00 00 FD 54 00 00 49 0B 79 CC .........T..I.y.
49 0B 79 CC 30 32 CC CC 30 32 CC CC 00 00 00 00 I.y.02..02......
00 00 00 00 00 00 00 00 00 00 ED A1 01 00 00 00 ................
6B 6E 6C 73 70 61 68 72 00 00 00 00 00 00 00 00 knlspahr........
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 14 00 00 00 00 00 00 00 ................
00 00 00 00 01 00 00 00 36 A3 1D 00 01 00 00 00 ........6.......
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 ........
** The volume Time Machine Backups could not be repaired.
volume type is pure HFS+
primary MDB is at block 0 0x00
alternate MDB is at block 0 0x00
primary VHB is at block 2 0x02
alternate VHB is at block 3263840174 0xc28a3fae
sector size = 512 0x200
VolumeObject flags = 0x07
total sectors for volume = 3263840176 0xc28a3fb0
total sectors for embedded volume = 0 0x00
CheckHFS returned 8, fsmodified = 1
Perhaps with more detailed reports when this issue happens, the bugs can be fixed down the road. Unfortunately Apple is unlikely to be receptive with the ReadyNAS in the mix, but I'm going to attempt to file a bug with them and see where it goes.
10 Replies
Replies have been turned off for this discussion
- Any word on this? I'm having the same problem and it is quite annoying.
- I had a second incident, but running the fsck_hfs process fixed it. I didn't gather the relevant logs as it was right before my recent move. No Time Capsule in the mix yet either.
Perhaps the recent 10.8.3 update will also help. I'll keep an eye on it now that my home network is almost fully back up. - I am also having this same issue.
My Backup is about 500 GB and is having to be redone every 2-3 days.
OS 10.7.5
Ready Nas Pro 6
Does not put much confidence in this source as a backup since it fails every couple of days. Would hate to have it not able to recover when I really need it.
Andrew - Added a 802.11ac based Airport Extreme to my network. Added an USB drive to it, for alternating backups to it and my ReadyNAS Duo v2. Another day, another corrupt backup on the ReadyNAS being repaired. So far, flawless backups to the Airport.
Still seems to be triggered by the laptop and the NAS having their backup session interrupted. Airport seems to handle this fine.
Is the Duo V2 just a dead end product now with the new OS stuff out? Haven't kept up with ReadyNAS news recently. I am following Marco Arment's experiences with a Synology unit though and his Macs. Wondering if they have the same problems there. I just want a reliable backup setup. - So far, backups to the Airport with a HFS+ disk attached have been 100% solid . Survives interruptions, and just works.
Duo V2 just again complained it needed to start another backup. Instead going to let the multi hour process run to fix it, again. Time to open a support ticket with Netgear directly I suppose, with no response on the boards. The problem is clearly the NAS. - I was hoping, netgear would be interested in finding problems as soon as the arise and read (and maybe write) here. But this problem persists a long time for me and not a single hint that it is being worked on.
Would you post your ticked id so that interested users can keep track of its status? - Thomas there is an RC for the Ultra which supports backups from Mavericks. Over time there have been firmware updates which have addressed issues.
- that's goos news, thank you.
although: "from time to time" made me laugh a little bit, because this problem seems to occur at least half a year for me and here in the forum for others too, so that raises my hope for (maybe) next week's release of mavericks and the release of a potential successor to 4.2.24 to my 3 readynas'es.
thanks! - Here is the 4.2.25 RC: http://www.readynas.com/forum/viewtopic.php?f=51&t=70385
You can see if that helps or wait for the production release.
Hopefully there will be a new firmware for the Duo V2 as well. 5.3.9 is currently in beta.
NETGEAR Academy
Boost your skills with the Netgear Academy - Get trained, certified and stay ahead with the latest Netgear technology!
Join Us!
