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
Skywalker wrote: mnc, do you have any AFP shares with guest access enabled on them?
Yup, I do. A couple of them, actually.
Is that related to the issue?
\marc- It's hard to say. It may be worth a try to disable guest access on all the shares to see if that makes a difference. It's a bit of a wild guess, but I've been thinking there's a chance that OSX may be getting confused if it connected to the box last using the guest UAM.
My other hunch, in your case, is a possible Bonjour discovery issue. We noticed in your logs a lot of bad packet errors, so perhaps it's just a network issue for a brief time when OSX is trying to look up the NAS via Bonjour. Are both systems on the same switch? If not, would it be possible to move them to the same switch for a while just as a test? Skywalker wrote: It's hard to say. It may be worth a try to disable guest access on all the shares to see if that makes a difference. It's a bit of a wild guess, but I've been thinking there's a chance that OSX may be getting confused if it connected to the box last using the guest UAM.
My other hunch, in your case, is a possible Bonjour discovery issue. We noticed in your logs a lot of bad packet errors, so perhaps it's just a network issue for a brief time when OSX is trying to look up the NAS via Bonjour. Are both systems on the same switch? If not, would it be possible to move them to the same switch for a while just as a test?
They are not, in fact, on the same switch -- but it would be easy to move them to the same switch.
I'll give that a try. If that doesn't help, I'll try removing the AFP guest access.
Could the bad packet errors be something wrong with the NAS itself? Perhaps the network interface going bad?mnc042 wrote: Could the bad packet errors be something wrong with the NAS itself? Perhaps the network interface going bad?
I doubt it, since you would usually see the ReadyNAS sending out bad packets and not even knowing about it. In this case it's receiving them. I've personally seen a bad switch cause that before at my house.Skywalker wrote: mnc042 wrote: Could the bad packet errors be something wrong with the NAS itself? Perhaps the network interface going bad?
I doubt it, since you would usually see the ReadyNAS sending out bad packets and not even knowing about it. In this case it's receiving them. I've personally seen a bad switch cause that before at my house.
Good enough. I'll give it a try and update here!
\marcSkywalker wrote: mnc042 wrote: Could the bad packet errors be something wrong with the NAS itself? Perhaps the network interface going bad?
I doubt it, since you would usually see the ReadyNAS sending out bad packets and not even knowing about it. In this case it's receiving them. I've personally seen a bad switch cause that before at my house.
Okay, I've moved things around and tried a whole bunch of combinations. All of which eventually generated the same error.
The original layout of my home network was thus:
Mac -> 5-port 10/100 Switch -> 16-port 10/100 Switch -> 24-port 10/100 Switch -> NAS
I swapped out a different 5-port 10/100 for the original, no improvement.
I removed the 16-port altogether, no improvement.
I finally removed all intervening switches so I had the Mac and the NAS on the same 24-port 10/100 switch, no improvement.
I've been watching the traffic with Wireshark and honestly I'm not seeing anything out of the ordinary. Can you give me some more specifics about what's being captured in the logs, what type of bad packet is the NAS seeing? Which file is showing the error, I can take a look at the logs on my end as well..
Thanks!
\marc- I lost your old logs. Can you re-send them? Have you tried disabling guest access to all your AFP shares yet?
Skywalker wrote: I lost your old logs. Can you re-send them? Have you tried disabling guest access to all your AFP shares yet?
Re-sent.
And drat, I forgot about turning off guest access. I'll do that now while you peruse the re-sent logs. :-)
Thanks again!
\marc- I just had the failure, first time in a few weeks. I will email the NAS logs now. Here is what I see on the Mac's system.log:
Oct 26 08:48:18 Kobe com.apple.backupd[17821]: Starting standard backup
Oct 26 08:48:18 Kobe com.apple.backupd[17821]: Attempting to mount network destination using URL: afp://[email protected]/ReadyNAS
Oct 26 08:48:19 Kobe com.apple.backupd[17821]: NetAuthConnectToServerSync failed with error: -6600 for url: afp://[email protected]/ReadyNAS
Oct 26 08:48:19 Kobe com.apple.backupd[17821]: 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 26 08:48:24: --- last message repeated 1 time ---
Oct 26 08:48:24 Kobe com.apple.backupd[17821]: Backup failed with error: 29
Let me know if you need anything else. - Just an update on my side, I disabled guest access and I haven't had the failure in a few days, but I have gone days in the past without seeing the error, only to have it re-appear daily with a vengeance, so I'm not sure I'd necessarily say my problem is solved..
Just wanted to check in..
\marc
NETGEAR Academy
Boost your skills with the Netgear Academy - Get trained, certified and stay ahead with the latest Netgear technology!
Join Us!
