July 14, 201114 yr I'm seeing this issue where my AFP shares just "shut-off" in 5.0b9. I get a bunch of these messages in my syslog: Jul 14 11:16:14 Tower shfs/user: shfs_setxattr: setxattr: /mnt/disk8/Backup (95) Operation not supported On my Mac (latest snow leopard) ==> /var/log/system.log <== Jul 14 13:05:02 MacPro login[2045]: USER_PROCESS: 2045 ttys003 Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 received event(s) VQ_NOTRESP (1) Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 type 'afpfs', mounted on '/Volumes/Books', from 'afp_2CHmYR0mbzVn0MLkAU1hBRbF-2.2d000003', not responding Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 type 'afpfs', mounted on '/Volumes/HD', from 'afp_2CHmYR0mbzVn0MLkAU1hBRbF-3.2d000004', not responding Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 type 'afpfs', mounted on '/Volumes/Movies', from 'afp_2CHmYR0mbzVn0MLkAU1hBRbF-4.2d000005', not responding Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 type 'afpfs', mounted on '/Volumes/Television', from 'afp_2CHmYR0mbzVn0MLkAU1hBRbF-6.2d000006', not responding Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 type 'afpfs', mounted on '/Volumes/Backup', from 'afp_2CHmYR0mbzVn0MLkAU1hBRbF-1.2d000007', not responding Jul 14 13:05:20 MacPro KernelEventAgent[56]: tid 00000000 found 5 filesystem(s) with problem(s) ==> /var/log/kernel.log <== Jul 14 13:05:20 MacPro kernel[0]: ASP_TCP Disconnect: triggering reconnect by bumping reconnTrigger from curr value 0 on so 0xdc1b018 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/Books prevTrigger 0 currTrigger 1 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/Books Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: posting to KEA EINPROGRESS for /Volumes/Books Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/Books Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/Movies prevTrigger 0 currTrigger 1 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progresAFP_VFS afpfs_DoReconnect: conns for /Volect to the server /Volumeumes/Ms/Books Jul 14 13:05:20 MacPro kernel[0]: ovies, going back to wait Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: Logging in with uam 8 /Volumes/Books Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/Backup prevTrigger 0 currTrigger 1 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Backup, going back to wait Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/Television prevTrigger 0 currTrigger 1 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Television, going back to wait Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect started /Volumes/HD prevTrigger 0 currTrigger 1 Jul 14 13:05:20 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/HD, going back to wait Jul 14 13:05:21 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Movies, going back to wait Jul 14 13:05:21 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Backup, going back to wait Jul 14 13:05:21 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Television, going back to wait Jul 14 13:05:21 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/HD, going back to wait Jul 14 13:05:22 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Movies, going back to wait Jul 14 13:05:22 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Backup, going back to wait Jul 14 13:05:22 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Television, going back to wait Jul 14 13:05:22 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/HD, going back to wait Jul 14 13:05:23 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/Books Jul 14 13:05:23 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Movies, going back to wait Jul 14 13:05:23 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Backup, going back to wait Jul 14 13:05:23 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/Television, going back to wait Jul 14 13:05:23 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: reconnect already in progress for /Volumes/HD, going back to wait ==> /var/log/system.log <== Jul 14 13:05:23 MacPro KernelEventAgent[56]: tid 00000000 received event(s) VQ_NOTRESP (1) ==> /var/log/kernel.log <== Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: Primary Reconnect failed 5 on /Volumes/Books Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: trying Secondary Reconnect on /Volumes/Books ==> /var/log/system.log <== Jul 14 13:05:24: --- last message repeated 3 times --- Jul 14 13:05:24 MacPro kernel[0]: Secondary Reconnect succeeded /Volumes/Books ==> /var/log/kernel.log <== Jul 14 13:05:24 MacPro kernel[0]: Secondary Reconnect succeeded /Volumes/Books Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 0 error 35 reqID 9215 flags 0x29 afpCmd 0x3C so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 1 error 35 reqID 9216 flags 0x29 afpCmd 0x3C so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 2 error 35 reqID 9217 flags 0x29 afpCmd 0x11 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 3 error 35 reqID 9218 flags 0x29 afpCmd 0x11 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 4 error 35 reqID 9219 flags 0x29 afpCmd 0x11 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 5 error 35 reqID 9220 flags 0x29 afpCmd 0x11 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 6 error 35 reqID 9222 flags 0x29 afpCmd 0x22 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 7 error 35 reqID 9223 flags 0x29 afpCmd 0x22 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 29 error 35 reqID 9212 flags 0x29 afpCmd 0x22 so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 30 error 35 reqID 9213 flags 0x29 afpCmd 0x3C so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: ASP_TCP CancelOneRequest: cancelling slot 31 error 35 reqID 9214 flags 0x29 afpCmd 0x3C so 0xdc1b018 Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: get the reconnect token Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: already reconnected socketID 1 on /Volumes/Movies Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: trying secondary reconnect /Volumes/Movies Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: already reconnected socketID 1 on /Volumes/Backup Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: trying secondary reconnect /Volumes/Backup Jul 14 13:05:24 MacPro kernel[0]: Secondary Reconnect succeeded /Volumes/Movies ==> /var/log/system.log <== Jul 14 13:05:24 MacPro kernel[0]: Secondary Reconnect succeeded /Volumes/Movies ==> /var/log/kernel.log <== Jul 14 13:05:24 MacPro kernel[0]: AFP_VFS afpfs_DoReconnect: get the reconnect token Jul 14 13:05:24 MacPro kernel[0]: Secondary Reconnect succeeded /Volumes/Backup
July 19, 201114 yr Yup, I'm experiencing the same exact output -- in both unRAID and OS X. Not sure what the issue is yet, but I'll keep digging around.. Do you happen to use speeding_ant's launchd script for WOL, automatic mount/dismount of your shares, etc.? EDIT: Check out this post in the unRAID Version 5.0b9 Announcement thread: http://lime-technology.com/forum/index.php?topic=13964.msg132771#msg132771 Specifically: A few people, including me, have noticed error messages like this in the syslog: Jul 16 22:29:02 unRAID shfs/user: shfs_setxattr: setxattr: /mnt/disk1/Audio (22) Invalid argument Jul 16 22:29:02 unRAID shfs/user: shfs_setxattr: setxattr: /mnt/disk1/BD-Backup (22) Invalid argument Jul 16 22:29:02 unRAID shfs/user: shfs_setxattr: setxattr: /mnt/disk1/Movies (22) Invalid argument Jul 16 22:29:02 unRAID shfs/user: shfs_setxattr: setxattr: /mnt/disk1/Software (22) Invalid argument Jul 16 22:29:02 unRAID shfs/user: shfs_setxattr: setxattr: /mnt/disk1/TV (22) Invalid argument I turned on afpd logging by adding this line to the /etc/netatalk/afpd.conf file -setuplog “default log_info /var/log/afpd.log” On restarting afpd, I was able to see this information in the afpd.log file: Jul 16 23:07:44.859913 afpd[1858] {volume.c:1907} (W:AFPDaemon): volume "Audio" does not support Extended Attributes, using ea:ad instead Jul 16 23:07:44.860087 afpd[1858] {volume.c:1907} (W:AFPDaemon): volume "BD-Backup" does not support Extended Attributes, using ea:ad instead Jul 16 23:07:44.860233 afpd[1858] {volume.c:1907} (W:AFPDaemon): volume "Movies" does not support Extended Attributes, using ea:ad instead Jul 16 23:07:44.860384 afpd[1858] {volume.c:1907} (W:AFPDaemon): volume "Software" does not support Extended Attributes, using ea:ad instead Jul 16 23:07:44.860490 afpd[1858] {volume.c:1907} (W:AFPDaemon): volume "TV" does not support Extended Attributes, using ea:ad instead Which corresponds to the messages above (ignore the time differences, I had to reboot; see below!). I think this means that the errors in the syslog can be safely ignored.
July 19, 201114 yr I've seen this disconnect issue before. It's unRAID based, netatalk has a few issues with connection stability. Specifically happens when you try to authenticate to AFP via another means (eg TimeMachine) whilst the computer has volumes already mounted. Apparently supposed to be fixed in 2.2.
July 19, 201114 yr I wasn't blaming your script But thought the "reconnect already in progress" may have been the script remounting the drives? Not sure
July 19, 201114 yr No worries. Didn't really jump to that conclusion, but did some testing to be sure! Cheers
Archived
This topic is now archived and is closed to further replies.