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
mhorn wrote: Attn: yoh-dah
Just sent email with my log files from my ReadyNAS.
I've also included the system.log from my mac (mac_system.log) which show the failures from the Mac side:
Oct 12 23:26:54 underdog com.apple.backupd[77961]: Starting standard backup
Oct 12 23:26:54 underdog com.apple.backupd[77961]: Attempting to mount network destination using URL: afp://[email protected]/ReadyNAS
Oct 12 23:26:55 underdog com.apple.backupd[77961]: NetAuthConnectToServerSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
Oct 12 23:26:55 underdog com.apple.backupd[77961]: 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.
Oct 12 23:27:00: --- last message repeated 1 time ---
Oct 12 23:27:00 underdog com.apple.backupd[77961]: Backup failed with error: 29
It would be great to figure this out as I backup three Macs in my home to the ReadyNAs.
--mark
Mark, do you see the errors on all 3 Macs?- I just went through a 49 GB Time Machine update to the ReadyNAS Pro without any problem. It seems to hang up for about 20 mins at the 43 GB mark, but it proceeded right to 49 GB after the delay. Perhaps it's a status update bug with Time Machine.
One thing to check is the unrecovered TCP retransmit errors (Duo & NV+ users, take a look ecounters.log in your logs). Keep track of the count before and after your backup. If that goes up, there could be something on your network that may be causing the Time Machine backups to fail. Bad cabling and flaky router or switch may cause problems. If at all possible, try running the backups directly connecting your Mac to the ReadyNAS (you'll need to set your Mac IP to static, i.e. 192.168.168.1 as the ReadyNAS will take on 192.168.168.168) and see if the problem still occurs. If so, try replacing the cable.
At the same time, we'll look on our side to see if there's anything we can figure out from the logs. Keep them coming.
Thanks!
8) - Many of us here (well... myself at least) are coming from Time Capsules (same network infrastructure, just using the NAS instead of TC as the backup destination). I think it's unlikely to be a network issue considering the multitude of setups in which this is occurring. Also, the size of the backup job has nothing to do with the issue. The backup fails at the authentication stage, before any backup data is transmitted.
Could be something slightly different about the Time Capsule's implementation of AFP authentication as it relates to Time Machine. Or something... rezonat0r wrote: Many of us here (well... myself at least) are coming from Time Capsules (same network infrastructure, just using the NAS instead of TC as the backup destination). I think it's unlikely to be a network issue considering the multitude of setups in which this is occurring. Also, the size of the backup job has nothing to do with the issue. The backup fails at the authentication stage, before any backup data is transmitted.
Could be something slightly different about the Time Capsule's implementation of AFP authentication as it relates to Time Machine. Or something...
I don't think you can rule out anything at this point, and we're trying to come up with a reproducible case so we have something to debug. Based on the postings, it looks like perhaps some sort of timeout could have affected the authentication. One of the logs we received had close to 15K TCP retransmits or which 130 were unrecovered, which essentially means there were unrecovered errors on the network. Whether that had anything to do with the authentication error is something I think would be useful.rezonat0r wrote: Many of us here (well... myself at least) are coming from Time Capsules (same network infrastructure, just using the NAS instead of TC as the backup destination). I think it's unlikely to be a network issue considering the multitude of setups in which this is occurring. Also, the size of the backup job has nothing to do with the issue. The backup fails at the authentication stage, before any backup data is transmitted.
Could be something slightly different about the Time Capsule's implementation of AFP authentication as it relates to Time Machine. Or something...
Just some information on my setup..
I back up 5 macs to two Time Capsules and the ReadyNAS, all on the same network (long story). Only the ReadyNAS is the one that gives any errors at all. I would think that if I were having network issues, I'd see failures from the Time Capsules as well..?
\marc- The issue is very sporadic for me. It can happen a couple of times in one day and then not occur again for a week or more.
Several times when it happens I check the net stats on the Mac and the send errors, recv errors and collisions are all zero. The Mac and Nas are the only two devices on the gigabit network. I installed new cables a few weeks ago and the problem happened before I changed them as well as afterwards.
I'll have to wait for the problem to occur again before I can grab the NAS log files. yoh-dah wrote: mhorn wrote: Attn: yoh-dah
Just sent email with my log files from my ReadyNAS.
I've also included the system.log from my mac (mac_system.log) which show the failures from the Mac side:
Oct 12 23:26:54 underdog com.apple.backupd[77961]: Starting standard backup
Oct 12 23:26:54 underdog com.apple.backupd[77961]: Attempting to mount network destination using URL: afp://[email protected]/ReadyNAS
Oct 12 23:26:55 underdog com.apple.backupd[77961]: NetAuthConnectToServerSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
Oct 12 23:26:55 underdog com.apple.backupd[77961]: 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.
Oct 12 23:27:00: --- last message repeated 1 time ---
Oct 12 23:27:00 underdog com.apple.backupd[77961]: Backup failed with error: 29
It would be great to figure this out as I backup three Macs in my home to the ReadyNAs.
--mark
Mark, do you see the errors on all 3 Macs?
Time Machine does fail on all three -- how often does seem a bit random.
I'll try to watch the mac system.log files when the failures occur. The log information above was from my mac which had a Time Machine failure last night.- Hi,
I have the same TM problems on my MacPro (Mac OS X 10.5.8, ReadyNAS Duo with firmware 4.1.6). Most of the time I see error 19 in the system.log of the Mac, e.g.:Sep 29 18:47:00 BigSwamp /System/Library/CoreServices/backupd[3448]: Backup requested by user
Sep 29 18:47:00 BigSwamp /System/Library/CoreServices/backupd[3448]: Starting standard backup
Sep 29 18:47:02 BigSwamp /System/Library/CoreServices/backupd[3448]: FSMountServerVolumeSync failed with error: -36 for url: afp://[email protected]/ReadyNAS
Sep 29 18:47:07 BigSwamp /System/Library/CoreServices/backupd[3448]: Backup failed with error: 19
Sometimes it is error 29:Oct 10 15:04:26 BigSwamp /System/Library/CoreServices/backupd[4169]: FSMountServerVolumeSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
Oct 10 15:04:26 BigSwamp /System/Library/CoreServices/backupd[4169]: 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.
Oct 10 15:04:31: --- last message repeated 1 time ---
Oct 10 15:04:31 BigSwamp /System/Library/CoreServices/backupd[4169]: Backup failed with error: 29
Boris - Had another failure today at 10:46am. I just forwarded the logs (which hopefully include the trace back to that time this morning). On the Mac side, the usual log:
10/14/09 10:46:19 AM /System/Library/CoreServices/backupd[75193] Starting standard backup
10/14/09 10:46:22 AM /System/Library/CoreServices/backupd[75193] FSMountServerVolumeSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
10/14/09 10:46:22 AM /System/Library/CoreServices/backupd[75193] 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.
10/14/09 10:46:22 AM /System/Library/CoreServices/backupd[75193] 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.
10/14/09 10:46:27 AM /System/Library/CoreServices/backupd[75193] Backup failed with error: 29
I hope this helps pinpoint the failure on the NAS in the logs...
Thanks!
\marc - mnc, do you have any AFP shares with guest access enabled on them?
NETGEAR Academy
Boost your skills with the Netgear Academy - Get trained, certified and stay ahead with the latest Netgear technology!
Join Us!
