Intermittent "permission" problem with AFP


Recommended Posts

I'm running 5.0-rc4 and trying to get a stable AFP setup working between my Mac Mini and my unRAID.  The AFP share (user share) is automounted on the Mac.  I'm seeing an intermittent issue where during larger transfers or ones with lots of little files it seems to "hiccup" part of the way through and claim that I don't have write permission to the share.  If I try the same exact move or copy operation a few seconds later it works fine, which seems to indicate that it's not actually a permissions issue.

 

I'm not really sure where to begin debugging this.  I don't see anything of note in the syslog corresponding to when the hiccups actually occur.  There are some things when AFP is first starting up that may or may not be a clue:

 

Jun 29 18:06:34 thedisk emhttp: Start AFP...
Jun 29 18:06:34 thedisk emhttp: shcmd (72): /etc/rc.d/rc.atalk start |& logger
Jun 29 18:06:34 thedisk logger: starting appletalk daemons: cnid_metad afpd
Jun 29 18:06:34 thedisk emhttp: shcmd (73): cp /etc/avahi/services/afp.service- /etc/avahi/services/afp.service
Jun 29 18:06:34 thedisk avahi-daemon[3482]: Files changed, reloading.
Jun 29 18:06:34 thedisk emhttp: shcmd (74): cp /etc/avahi/services/smb.service- /etc/avahi/services/smb.service
Jun 29 18:06:34 thedisk avahi-daemon[3482]: Loading service file /services/afp.service.
Jun 29 18:06:34 thedisk avahi-daemon[3482]: Files changed, reloading.
Jun 29 18:06:34 thedisk avahi-daemon[3482]: Service group file /services/smb.service changed, reloading.
Jun 29 18:06:34 thedisk emhttp: shcmd (75): /usr/local/sbin/emhttp_event svcs_restarted
Jun 29 18:06:34 thedisk emhttp_event: svcs_restarted
Jun 29 18:06:35 thedisk avahi-daemon[3482]: Service "thedisk" (/services/afp.service) successfully established.
Jun 29 18:06:35 thedisk avahi-daemon[3482]: Service "thedisk-SMB" (/services/smb.service) successfully established.
Jun 29 18:07:13 thedisk ntpd_intres[1252]: DNS pool.ntp.org -> 74.200.253.228
Jun 29 18:07:14 thedisk ntpd[1241]: Listen normally on 2 eth0 192.168.1.97 UDP 123
Jun 29 18:07:14 thedisk ntpd[1241]: new interface(s) found: waking up resolver
Jun 29 18:07:42 thedisk cnid_dbd[3935]: error opening DB environment: DB_RUNRECOVERY: Fatal error, run database recovery
Jun 29 18:07:42 thedisk afpd[3926]: read: Connection reset by peer
Jun 29 18:07:42 thedisk cnid_metad[3750]: error in sendmsg: Broken pipe
Jun 29 18:07:42 thedisk afpd[3926]: read: Connection reset by peer
Jun 29 18:07:43 thedisk cnid_dbd[3936]: error opening DB environment: DB_RUNRECOVERY: Fatal error, run database recovery
Jun 29 18:07:43 thedisk afpd[3926]: read: Connection reset by peer
Jun 29 18:07:44 thedisk cnid_dbd[3943]: error opening DB environment: DB_RUNRECOVERY: Fatal error, run database recovery
Jun 29 18:07:44 thedisk afpd[3926]: read: Connection reset by peer
Jun 29 18:07:45 thedisk cnid_metad[3944]: Multiple attempts to start CNID db daemon for "/mnt/user/Music" failed, wiping the slate clean...
Jun 29 18:07:45 thedisk cnid_dbd[3944]: main: too many CNID db opening attempts, wiping the slate clean
Jun 29 18:07:52 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:977 for /mnt/user/Music (/mnt/user/Music)
Jun 29 18:07:52 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:976 for /mnt/user/Backup (/mnt/user/Backup)
Jun 29 18:07:52 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:975 for /mnt/user/Backup (/mnt/user/Backup)
Jun 29 18:07:52 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:974 for /mnt/user/Audiobooks (/mnt/user/Audiobooks)
Jun 29 18:16:27 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:973 for /mnt/user/Backup (/mnt/user/Backup)
Jun 29 18:16:27 thedisk mountd[3744]: authenticated mount request from 192.168.1.99:972 for /mnt/user/Backup (/mnt/user/Backup)

 

Beyond that, are there any other logs I should be looking in, or can someone point me in the direction of things I might be able to tweak with the AFP config?  Any ideas?

Link to comment

Upon watching the log for a while longer, I'm seeing this type of thing repeated over and over:

 

Jun 29 02:11:41 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "@"
Jun 29 02:11:52 thedisk last message repeated 4 times
Jun 29 02:11:54 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "\200"
Jun 29 02:12:13 thedisk last message repeated 8 times
Jun 29 02:12:13 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "@"
Jun 29 02:12:14 thedisk last message repeated 2 times
Jun 29 02:12:14 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "\200"
Jun 29 02:12:19 thedisk last message repeated 13 times
Jun 29 02:12:20 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "@"
Jun 29 02:12:23 thedisk last message repeated 9 times
Jun 29 02:12:23 thedisk afpd[2236]: deletecurdir: error deleting .AppleDouble in "\200"
Jun 29 02:12:40 thedisk last message repeated 30 times

 

I don't really understand what a CNID database is (the thing having issues in the log in the original post) but some googling tells me it might be related to (or contained in?) these .AppleDouble files.  I notice that these .AppleDoubles also stick around on the cache drive even after the mover runs, causing all of my shares to stay orange.  Not sure if that's known/expected behavior.

Link to comment

Which Nic are you using? The message repated lines in you syslog indicate that there might be a problem with it.

 

Hm..  not sure what about that log is telling you there's a problem with the NIC, but here's some info:

 

root@thedisk:/proc/net# dmesg | grep eth0
e1000e 0000:00:19.0: eth0: (PCI Express:2.5GT/s:Width x1) c8:60:00:8a:71:1c
e1000e 0000:00:19.0: eth0: Intel(R) PRO/1000 Network Connection
e1000e 0000:00:19.0: eth0: MAC: 10, PHY: 11, PBA No: FFFFFF-0FF
e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx

 

I think it's a standard Intel GBit NIC, and it seems to be working fine otherwise.

Link to comment

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Reply to this topic...

×   Pasted as rich text.   Restore formatting

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.