NETGEAR is aware of a growing number of phone and online scams. To learn how to stay safe click here.
Forum Discussion
Periodic (daily) Time Machine failures
I am running TM on an iMac with 10.5.8 to a Duo running 4.1.6. However I am getting a failure about once a day where TM pops up a dialog saying the network volume could not be mounted because of a problem with the username or password. It is very odd because it will do its hourly backup just fine for some period of time (a day or maybe a bit longer) before giving me this error. If I go to the TM Preferences I have to re-enter the username and password, then all is fine again for a day or so. This happened again just now and I snagged the Duo logs and also took a look at the Mac log. On there I see this series of possibly related messages:
Aug 16 17:07:40 Kobe kernel[0]: AFP_VFS afpfs_mount: /Volumes/ReadyNAS, pid 4993
Aug 16 17:07:40 Kobe Bonjour Mounter[267]: DiskAppearedCallback diskDescription = {\n DAVolumeKind = afpfs;\n DAVolumeMountable = 1;\n DAVolumeName = ReadyNAS;\n DAVolumeNetwork = 1;\n DAVolumePath = file://localhost/Volumes/ReadyNAS/;\n}
Aug 16 17:07:42 Kobe [0x0-0x14c14c].com.apple.systempreferences[4987]: chown: /Volumes/ReadyNAS/.001ec20ffc9e: Operation not permitted
Aug 16 17:07:43: --- last message repeated 1 time ---
Aug 16 17:07:43 Kobe kernel[0]: AFP_VFS afpfs_unmount: /Volumes/ReadyNAS, flags 0, pid 4998
Aug 16 17:07:43 Kobe Finder[161]: StatusMonitor::volumesChangedCallBack returned -47
Aug 16 17:07:43 Kobe kernel[0]: ASP_TCP do_thread_read: no reqInfo found for reqID 1
Aug 16 17:07:43 Kobe Bonjour Mounter[267]: DiskDisappearedCallback diskDescription = {\n DAVolumeKind = afpfs;\n DAVolumeMountable = 1;\n DAVolumeName = ReadyNAS;\n DAVolumeNetwork = 1;\n DAVolumePath = file://localhost/Volumes/ReadyNAS/;\n}
Aug 16 17:07:43 Kobe kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 29 error 89 reqID 30 flags 0x9 afpCmd 0x14 so 0x7e7a330
In Duo afp.log
Aug 16 17:07:42 cnid_dbd[29190][logger.c:255]: I:Logger: doing log_setup, type 0, level 50, filename "/var/log/netatalk.log"
Aug 16 17:07:42 cnid_dbd[29190][logger.c:395]: D7:Logger: log_file_arr[0] now contains: {log_filename:/var/log/netatalk.log, log_file:(nil), log_level: 50}
Aug 16 17:07:42 cnid_dbd[29190][logger.c:398]: D5:Logger: log_setup[0] done
Aug 16 17:07:42 cnid_dbd[29190][main.c:210]: I:CNID: Setting uid/gid to 0/0
Aug 16 17:07:42 cnid_dbd[29190][main.c:309]: I:CNID: Startup, DB dir /c/.timemachine/.AppleDB
Any idea how I prevent this from happening? It means if I'm not in front of the Mac for awhile the TM backups stop.
Aug 16 17:07:40 Kobe kernel[0]: AFP_VFS afpfs_mount: /Volumes/ReadyNAS, pid 4993
Aug 16 17:07:40 Kobe Bonjour Mounter[267]: DiskAppearedCallback diskDescription = {\n DAVolumeKind = afpfs;\n DAVolumeMountable = 1;\n DAVolumeName = ReadyNAS;\n DAVolumeNetwork = 1;\n DAVolumePath = file://localhost/Volumes/ReadyNAS/;\n}
Aug 16 17:07:42 Kobe [0x0-0x14c14c].com.apple.systempreferences[4987]: chown: /Volumes/ReadyNAS/.001ec20ffc9e: Operation not permitted
Aug 16 17:07:43: --- last message repeated 1 time ---
Aug 16 17:07:43 Kobe kernel[0]: AFP_VFS afpfs_unmount: /Volumes/ReadyNAS, flags 0, pid 4998
Aug 16 17:07:43 Kobe Finder[161]: StatusMonitor::volumesChangedCallBack returned -47
Aug 16 17:07:43 Kobe kernel[0]: ASP_TCP do_thread_read: no reqInfo found for reqID 1
Aug 16 17:07:43 Kobe Bonjour Mounter[267]: DiskDisappearedCallback diskDescription = {\n DAVolumeKind = afpfs;\n DAVolumeMountable = 1;\n DAVolumeName = ReadyNAS;\n DAVolumeNetwork = 1;\n DAVolumePath = file://localhost/Volumes/ReadyNAS/;\n}
Aug 16 17:07:43 Kobe kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 29 error 89 reqID 30 flags 0x9 afpCmd 0x14 so 0x7e7a330
In Duo afp.log
Aug 16 17:07:42 cnid_dbd[29190][logger.c:255]: I:Logger: doing log_setup, type 0, level 50, filename "/var/log/netatalk.log"
Aug 16 17:07:42 cnid_dbd[29190][logger.c:395]: D7:Logger: log_file_arr[0] now contains: {log_filename:/var/log/netatalk.log, log_file:(nil), log_level: 50}
Aug 16 17:07:42 cnid_dbd[29190][logger.c:398]: D5:Logger: log_setup[0] done
Aug 16 17:07:42 cnid_dbd[29190][main.c:210]: I:CNID: Setting uid/gid to 0/0
Aug 16 17:07:42 cnid_dbd[29190][main.c:309]: I:CNID: Startup, DB dir /c/.timemachine/.AppleDB
Any idea how I prevent this from happening? It means if I'm not in front of the Mac for awhile the TM backups stop.
82 Replies
Replies have been turned off for this discussion
- An update, this error happened for the second time today. This time when it happened I opened up the Keychain to ensure the username and password are stored there correctly. They are and there is only one entry in the Keychain.
At the time this most recent instance occurred I was doing I large copy from the NAS drive to an external USB drive. I'm wondering if there is a time out. - Same issue here, on multiple Macs running 10.5.8, ReadyNAS NV+ running 4.1.5.
- After having seen this error regularly it has recently stopped appearing. I upgraded to Snow Leopard Friday and haven't seen it since then. But the errors stopped appearing about a week before that.
- Is Time Machine working for you under Snow Leopard?
- Yes, I expected trouble but it has been trouble free.
- Just had my first failure of this kind on my main Snow Leopard machine. So the problem is still there.
roadfun wrote: Just had my first failure of this kind on my main Snow Leopard machine. So the problem is still there.
Same problem here!
It happens seemingly randomly, but then when Time Machine goes to try again, it succeeds.
If I try to manually run a Time Machine backup, the volume mounts fine.
Can't quite make it happen manually but it happens randomly on ALL my macs eventually during the course of a day.
Anyone have any suggestions/ideas? Backups that give errors tend to make me nervous. :-)
Thanks!- So every time this happens on my Mac, this error is logged in the console:
9/10/09 12:35:59 PM /System/Library/CoreServices/backupd[4092] Starting standard backup
9/10/09 12:36:02 PM /System/Library/CoreServices/backupd[4092] FSMountServerVolumeSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
9/10/09 12:36:02 PM /System/Library/CoreServices/backupd[4092] Authentication error - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
9/10/09 12:36:02 PM /System/Library/CoreServices/backupd[4092] Authentication error - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
9/10/09 12:36:07 PM /System/Library/CoreServices/backupd[4092] Backup failed with error: 29
Then, the backup proceeds normally the next time Time Machine is fired up automatically:
9/10/09 1:36:00 PM /System/Library/CoreServices/backupd[4092] Starting standard backup
9/10/09 1:36:02 PM /System/Library/CoreServices/backupd[4092] Mounted network destination using URL: afp://[email protected]/ReadyNAS
9/10/09 1:36:02 PM /System/Library/CoreServices/backupd[4092] Backup destination mounted at path: /Volumes/ReadyNAS
9/10/09 1:36:05 PM /System/Library/CoreServices/backupd[4092] Disk image /Volumes/ReadyNAS/Egwene_001d4f49f3a4.sparsebundle mounted at: /Volumes/Backup of Egwene
9/10/09 1:36:05 PM /System/Library/CoreServices/backupd[4092] Backing up to: /Volumes/Backup of Egwene/Backups.backupdb
9/10/09 1:36:16 PM /System/Library/CoreServices/backupd[4092] No pre-backup thinning needed: 1.44 GB requested (including padding), 1.11 TB available
9/10/09 1:36:16 PM /System/Library/CoreServices/backupd[4092] Waiting for index to be ready (906 > 0)
9/10/09 1:36:55 PM /System/Library/CoreServices/backupd[4092] Copied 1 files (6 KB) from volume Storage.
9/10/09 1:37:34 PM /System/Library/CoreServices/backupd[4092] Copied 882 files (6.8 MB) from volume Egwene.
9/10/09 1:37:38 PM /System/Library/CoreServices/backupd[4092] Copied 887 files (6.8 MB) from volume StorageRAID.
9/10/09 1:37:38 PM /System/Library/CoreServices/backupd[4092] No pre-backup thinning needed: 1.43 GB requested (including padding), 1.11 TB available
9/10/09 1:37:42 PM /System/Library/CoreServices/backupd[4092] Copied 1 files (6 KB) from volume Storage.
9/10/09 1:37:53 PM /System/Library/CoreServices/backupd[4092] Copied 425 files (6 KB) from volume Egwene.
9/10/09 1:37:57 PM /System/Library/CoreServices/backupd[4092] Copied 430 files (6 KB) from volume StorageRAID.
9/10/09 1:38:00 PM /System/Library/CoreServices/backupd[4092] Starting post-backup thinning
9/10/09 1:38:10 PM /System/Library/CoreServices/backupd[4092] Deleted backup /Volumes/Backup of Egwene/Backups.backupdb/Egwene/2009-09-09-132812: 1.11 TB now available
9/10/09 1:38:19 PM /System/Library/CoreServices/backupd[4092] Deleted backup /Volumes/Backup of Egwene/Backups.backupdb/Egwene/2009-09-09-122809: 1.11 TB now available
9/10/09 1:38:19 PM /System/Library/CoreServices/backupd[4092] Post-back up thinning complete: 2 expired backups removed
9/10/09 1:38:19 PM /System/Library/CoreServices/backupd[4092] Backup completed successfully.
9/10/09 1:38:22 PM /System/Library/CoreServices/backupd[4092] Ejected Time Machine disk image.
9/10/09 1:38:22 PM /System/Library/CoreServices/backupd[4092] Ejected Time Machine network volume.
Is this helpful to know? Error -6600 isn't terribly helpful, nothing much turns up when searching for it (aside from 'Yeah, that's an authentication error.').
Any ideas? This happens to me about once a day, sometimes twice.
Thanks!
\marc - I am having exactly the same issue. I don't change anything, don't re-enter username or password. Next time Time Machine tries, it works normally.
Has anyone discovered a root cause? It could be a Time Machine bug, or some problem with the ReadyNAS.
Thanks! - I guess it may be some sort of time out but not sure. Like the others, mine will work the next time.
NETGEAR Academy
Boost your skills with the Netgear Academy - Get trained, certified and stay ahead with the latest Netgear technology!
Join Us!
