[4.1.9-T2] First AFP connect fails after ReadyNAS Duo reboot

[ianch99]

Seeing this problem since I upgraded from 4.1.6 to 4.1.9-T2. In a nutshell, if you connect (from Lion) to our ReadyNAS Duo via AFP, you will get an error the first time. From then on, until the Duo is restarted, subsequent connects are ok. The Duo shuts down over night hence the issue.

Here is the problem in terms of the timing and logs:

Code: Select all

Before first connect (after Duo has re-booted)

    NAS log entries:
   
    ian@ianch-nas:/var/log$ grep "Mar 20" daemon.log | grep -i afp
    Mar 20 06:00:56 ianch-nas avahi-daemon[879]: Loading service file /etc/avahi/services/afp.service.
    Mar 20 06:00:58 ianch-nas avahi-daemon[879]: Service "ianch-nas (AFP)" (/etc/avahi/services/afp.service) successfully established.
    Mar 20 06:02:17 ianch-nas afpd[1266]: AFP/TCP started, advertising 192.168.0.2:548 (2-2-1-p6)


First connect (FAILS):

    NAS log entries:
   
    ian@ianch-nas:/var/log$ grep "Mar 20" daemon.log | grep -i afp
    Mar 20 06:00:56 ianch-nas avahi-daemon[879]: Loading service file /etc/avahi/services/afp.service.
    Mar 20 06:00:58 ianch-nas avahi-daemon[879]: Service "ianch-nas (AFP)" (/etc/avahi/services/afp.service) successfully established.
    Mar 20 06:02:17 ianch-nas afpd[1266]: AFP/TCP started, advertising 192.168.0.2:548 (2-2-1-p6)
    Mar 20 08:24:58 ianch-nas afpd[1266]: AFP/TCP started, advertising 192.168.0.2:548 (2-2-1-p6)

    Mac error:

    error popup "There was a problem connecting to the server “ianch-nas”"
   
    Mac log entries:

    20/03/2012 08:24:57.000 kernel: AppleSRP started.
    20/03/2012 08:24:58.000 kernel: ASP_TCP CancelOneRequest: cancelling slot 0 error 89 reqID 1 flags 0x9 afpCmd 0xF so 0x151a9e68

Second connect (OK):

    NAS log entries:
   
    ian@ianch-nas:/var/log$ grep "Mar 20" daemon.log | grep -i afp
    Mar 20 06:00:56 ianch-nas avahi-daemon[879]: Loading service file /etc/avahi/services/afp.service.
    Mar 20 06:00:58 ianch-nas avahi-daemon[879]: Service "ianch-nas (AFP)" (/etc/avahi/services/afp.service) successfully established.
    Mar 20 06:02:17 ianch-nas afpd[1266]: AFP/TCP started, advertising 192.168.0.2:548 (2-2-1-p6)
    Mar 20 08:24:58 ianch-nas afpd[1266]: AFP/TCP started, advertising 192.168.0.2:548 (2-2-1-p6)
    Mar 20 08:28:28 ianch-nas afpd[3685]: AFP3.3 Login by admin
   
    Mac log entries:
   
    20/03/2012 08:24:57.000 kernel: AppleSRP started.
    20/03/2012 08:24:58.000 kernel: ASP_TCP CancelOneRequest: cancelling slot 0 error 89 reqID 1 flags 0x9 afpCmd 0xF so 0x151a9e68
    20/03/2012 08:28:27.000 kernel: ASP_TCP CheckReqQueueSize: increasing req queue from 32 to 128 entries. so 0xea6ba10
    20/03/2012 08:28:28.937 BBDaemon: IOBSDNameMatching returned a NULL dictionary.
    20/03/2012 08:28:28.937 BBDaemon: IOBSDNameMatching returned a NULL dictionary.
    20/03/2012 08:28:28.976 mds: ERROR: _MDSChannelInitForAFP: AFPSendSpotLightRPC failed -1
    20/03/2012 08:28:29.000 kernel: AFP_VFS afpfs_mount: /Volumes/media, pid 503


It is like the AFP "listener" which was started when the Duo re-booted (@06:02) stops and is then re-started after the (failed) first AFP connect?

[mdgm]

Can you try T6?: http://www.readynas.com/forum/viewtopic.php?f=17&t=59222

Though not mentioned in the release notes there is an update to the AFP service in T6.

[matt_hargett]

Can you try T6?: http://www.readynas.com/forum/viewtopic.php?f=17&t=59222

Though not mentioned in the release notes there is an update to the AFP service in T6.

T6 also has a major regression in samba functionality (see my other post and other people's reports). What information can we provide to help debug/resolve these issues? Im' happy to provide remote shell access or to bring in my device, if you guys are in the SF bay area.

[Grievous]

Yes, please update to T-6 and let us know if the behavior you're seeing with the current T-2 beta changes.

[ianch99]

Now on 4.1.9-T6 but still have the first connect problem.

When I was on 4.1.6 + Lion, I had to use this workaround: http://support.apple.com/kb/HT4700. Just to make sure, I have removed the /Library/Preferences/com.apple.AppleShareClient.plist file and rebooted to revert to (Lion) defaults.

After rebooting the Duo and Mac, log entries are listed below. The AFP messages now seem to be in netatalk.log in this build ...

Code: Select all

Duo start-up:

Mar 21 09:14:52.115919 afpd[1236] {status.c:740} (I:AFPDaemon):  "ianch-nas"'s signature is  42D0D918E181E9412C87FBF4A81BA8D0
Mar 21 09:14:52.171470 afpd[1236] {dsi_tcp.c:318} (I:DSI): dsi_tcp_init: socket: Address family not supported by protocol
Mar 21 09:14:52.176359 afpd[1236] {afp_config.c:372} (N:AFPDaemon): AFP/TCP started, advertising 192.168.0.2:548 (2-2-2)
Mar 21 09:18:11.139245 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "No User Authent" available
Mar 21 09:18:11.139486 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "Cleartxt Passwrd" available
Mar 21 09:18:11.139646 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "DHX2" available
Mar 21 09:18:11.139806 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "DHCAST128" available
Mar 21 09:18:11.221289 afpd[1236] {volume.c:2213} (I:AFPDaemon): read-only volume 'squeezeboxserver', can't test for EA support, disabling EAs
Mar 21 09:18:11.221730 afpd[1236] {cnid.c:53} (I:AFPDaemon): Registering CNID module [dbd]
Mar 21 09:18:11.221931 afpd[1236] {cnid.c:53} (I:AFPDaemon): Registering CNID module [tdb]

<first connect>

Mac:

21/03/2012 09:23:45.000 kernel: AppleSRP started.
21/03/2012 09:23:45.000 kernel: ASP_TCP CancelOneRequest: cancelling slot 0 error 89 reqID 1 flags 0x9 afpCmd 0xF so 0x1539838c

Duo:

Mar 21 09:23:44.494716 afpd[1236] {main.c:440} (I:AFPDaemon): re-reading configuration file
Mar 21 09:23:44.527983 afpd[1236] {status.c:740} (I:AFPDaemon):  "ianch-nas"'s signature is  42D0D918E181E9412C87FBF4A81BA8D0
Mar 21 09:23:44.605959 afpd[1236] {dsi_tcp.c:318} (I:DSI): dsi_tcp_init: socket: Address family not supported by protocol
Mar 21 09:23:44.607702 afpd[1236] {afp_config.c:372} (N:AFPDaemon): AFP/TCP started, advertising 192.168.0.2:548 (2-2-2)

<second connect>

Mac:

21/03/2012 09:24:21.000 kernel: ASP_TCP CheckReqQueueSize: increasing req queue from 32 to 128 entries. so 0x126267e4
21/03/2012 09:24:22.563 BBDaemon: IOBSDNameMatching returned a NULL dictionary.
21/03/2012 09:24:22.563 BBDaemon: IOBSDNameMatching returned a NULL dictionary.
21/03/2012 09:24:22.609 mds: ERROR: _MDSChannelInitForAFP: AFPSendSpotLightRPC failed -1
21/03/2012 09:24:23.000 kernel: AFP_VFS afpfs_mount: /Volumes/media, pid 511

Duo:

Mar 21 09:24:20.539125 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "No User Authent" available
Mar 21 09:24:20.539345 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "Cleartxt Passwrd" available
Mar 21 09:24:20.539526 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "DHX2" available
Mar 21 09:24:20.539686 afpd[1236] {auth.c:136} (I:AFPDaemon): uam: "DHCAST128" available
Mar 21 09:24:20.633995 afpd[1236] {volume.c:2213} (I:AFPDaemon): read-only volume 'squeezeboxserver', can't test for EA support, disabling EAs
Mar 21 09:24:20.670047 afpd[1236] {main.c:214} (I:AFPDaemon): child[1958]: exited 1
Mar 21 09:24:20.677782 afpd[1959] {dsi_tcp.c:212} (I:DSI): AFP/TCP session from 192.168.0.10:49489
Mar 21 09:24:20.688444 afpd[1236] {main.c:216} (I:AFPDaemon): child[1959]: done
Mar 21 09:24:20.941009 afpd[1960] {dsi_tcp.c:212} (I:DSI): AFP/TCP session from 192.168.0.10:49492
Mar 21 09:24:20.958764 afpd[1960] {uams_dhx2_pam.c:321} (I:UAMS): DHX2 login: admin
Mar 21 09:24:21.973434 afpd[1960] {uams_dhx2_pam.c:210} (I:UAMS): PAM DHX2: PAM Success
Mar 21 09:24:21.993373 afpd[1960] {uams_dhx2_pam.c:698} (I:UAMS): DHX2: PAM Auth OK!
Mar 21 09:24:21.993634 afpd[1960] {auth.c:270} (N:AFPDaemon): AFP3.3 Login by admin
Mar 21 09:24:22.037041 afpd[1960] {volume.c:2213} (I:AFPDaemon): read-only volume 'squeezeboxserver', can't test for EA support, disabling EAs
Mar 21 09:24:22.040768 afpd[1960] {volume.c:2143} (I:AFPDaemon): CNID server: localhost:4700
Mar 21 09:24:22.540889 afpd[1236] {main.c:214} (I:AFPDaemon): child[1961]: exited 1
Mar 21 09:24:22.635177 afpd[1962] {dsi_tcp.c:212} (I:DSI): AFP/TCP session from 192.168.0.10:49494
Mar 21 09:24:22.645478 afpd[1236] {main.c:216} (I:AFPDaemon): child[1962]: done
Mar 21 09:24:25.783434 afpd[1965] {dsi_tcp.c:212} (I:DSI): AFP/TCP session from 192.168.0.10:49496
Mar 21 09:24:25.790408 afpd[1236] {main.c:214} (I:AFPDaemon): child[1964]: exited 1
Mar 21 09:24:25.799586 afpd[1236] {main.c:216} (I:AFPDaemon): child[1965]: done


I noticed someone else has posted what seems to be the same problem? http://www.readynas.com/forum/viewtopic.php?f=28&t=60692

[ianch99]

What is the best way of getting this resolved?

[ianch99]

Problem still present in 4.1.9