AFP not setup right or is something wrong?

[joshnerl]

I need some help figuring out if I set something up wrong or if there's something wrong with my FN box.

FN box is 8.0.4p2 64 bit, Pen G620, 16g, about 2 months old. FN box name is "tuck". Basic home setup is that I have 3 computers and the FN box. One Win7 box to do dvd rips/processing and 2 macs (One 10.7.4, one 10.8) for viewing/sharing iTunes. I use one username "joshnerl" to access the FN box from all computers.

When I setup tuck, i setup one volume called "tuckmov" for all my movies, tv shows, etc. I setup another for time machine and basic storage called tuckstor. Then I setup both CIFS and AFP shares to the same path for movies - in other words, I made a tuckmovafp and a tuckmovcifs and they both go directly to /mnt/tuckmov/. Finally I setup time machine to run to a volume in tuckstor called tm.

Here's my problem. Since I started this new box, the logging has been spitting out a lot of messages and I'm not smart enough to know if they're a problem or not. Stuff like this:

Aug 3 08:33:59 tuck last message repeated 23 times
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:33:59 tuck afpd[42153]: AFP3.3 Login by joshnerl
Aug 3 08:33:59 tuck afpd[42153]: afp_disconnect: trying primary reconnect
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: killing new session child[42153] after transfer
Aug 3 08:33:59 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43231 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43232 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43233 / cmd: AFP_GETFLDRPARAM
Aug 3 08:33:59 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:33:59 tuck last message repeated 33 times
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:33:59 tuck afpd[42154]: AFP3.3 Login by joshnerl
Aug 3 08:33:59 tuck afpd[42154]: afp_disconnect: trying primary reconnect
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: killing new session child[42154] after transfer
Aug 3 08:33:59 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43348 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43349 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[42145]: afp_disconnect: primary reconnect succeeded
Aug 3 08:33:59 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:33:59 tuck last message repeated 5 times
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:33:59 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:33:59 tuck afpd[42155]: AFP3.3 Login by joshnerl
Aug 3 08:33:59 tuck afpd[42155]: afp_disconnect: trying primary reconnect
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: killing new session child[42155] after transfer
Aug 3 08:33:59 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43380 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43381 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[42146]: afp_disconnect: primary reconnect succeeded
Aug 3 08:34:00 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:34:00 tuck afpd[42157]: AFP3.3 Login by joshnerl
Aug 3 08:34:00 tuck afpd[42157]: afp_disconnect: trying primary reconnect
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: killing new session child[42157] after transfer
Aug 3 08:34:00 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:34:00 tuck afpd[41962]: AFP Replay Cache match: id: 43396 / cmd: AFP_LISTEXTATTR
Aug 3 08:34:00 tuck afpd[42147]: afp_disconnect: primary reconnect succeeded
Aug 3 08:34:00 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:34:00 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:34:00 tuck afpd[42160]: AFP3.3 Login by joshnerl
Aug 3 08:34:00 tuck afpd[42160]: afp_disconnect: trying primary reconnect
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: killing new session child[42160] after transfer
Aug 3 08:34:00 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:34:00 tuck afpd[41962]: AFP Replay Cache match: id: 43409 / cmd: AFP_LISTEXTATTR
Aug 3 08:34:00 tuck afpd[42148]: afp_disconnect: primary reconnect succeeded
Aug 3 08:34:00 tuck afpd[41962]: sys_getextattr_size: error: Result too large
Aug 3 08:34:00 tuck last message repeated 15 times
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_stream_read: len:0, unexpected EOF
Aug 3 08:34:00 tuck afpd[41962]: dsi_disconnect: entering disconnected state
Aug 3 08:34:00 tuck afpd[42161]: AFP3.3 Login by joshnerl
Aug 3 08:34:00 tuck afpd[42161]: afp_disconnect: trying primary reconnect
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:34:00 tuck afpd[2023]: Reconnect: killing new session child[42161] after transfer
Aug 3 08:34:00 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect
Aug 3 08:34:00 tuck afpd[41962]: AFP Replay Cache match: id: 43463 / cmd: AFP_LISTEXTATTR

Now i never get more than 10-15 minutes between line items - ever. It's like there's constant heartbeat checks or something. About two weeks ago, my macs stopped showing artwork associated with the movie files in iTunes. When I do a "get info" on the individual files in itunes, the artwork shows back up. Then on one of my macs (10.7.4), I'm now getting a message about every 3 days that it wants to create a new time machine backup because there was something wrong with the old one. I let it recreate the backup on 7/31 and now it's telling me it wants to do it again. Last straw is that I have my macs connect automatically to tuck when they startup. In the last week or so, when I sit down at one of them, tuck isn't mounted. It's like it connects on startup, then loses it at some point.

Bottom line question is did i mess something up by pointing both AFP and CIFS shares to the same directory, do I have a problem with my files, is there a problem with AFP on FN? I just need some help deciding which rabbit hole to dive into. Any help or troubleshooting advice would be appreciated.

Josh

 

[seggerman]

Hi Josh,

since the errors are all AFP related, can you say when (using which AFP share) these occur? Can you maybe disable the shares individually to then see with which it then occurs.

Something that I noticed is that your tuckmovcifs and tuckmovafp point to the same directory. I know that cifs and afp store metadata/extended attributes in some files (.appleDB etc..) can this be "killing" your system? I think that I read something that some settings should not be enabled (example AFPv3) if this is also accessed by an "non-afp" share.

Maybe you can do some experimenting.

Best

Alexander

 

[joshnerl]

Thanks for jumping in on this one. This may be semantics, but I'm not getting "errors", i'm getting those messages in the log constantly. It could be because both of the macs startup in the morning and auto-open iTunes so the connection is constantly open, but I'm thinking that can't be a stretch right? I mean regardless of what the AFP share is being used for, having it open to networked macs has to be possible.

I checked the share settings and none of them have the AFP3 Unix Privs box checked. I checked the "no .appledouble" box on one of the shares and the messages continue. All other settings are default or unchecked.

 

[seggerman]

Correct, they are just messages. But maybe you can limit the shares and see when/during which action they pop up.

I use freenas as a timemachine and as a filestore.

The message:
Aug 3 08:33:59 tuck afpd[42155]: afp_disconnect: trying primary reconnect
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: transfering session to child[41962]
Aug 3 08:33:59 tuck afpd[2023]: Reconnect: killing new session child[42155] after transfer
Aug 3 08:33:59 tuck afpd[41962]: afp_dsi_transfer_session: succesfull primary reconnect

is somewhat related to the Time Machine backup. At least that I deduct from the log. But this message maybe is there once a day. Not as often as you received.

Occasionally I get the 'dsi_stream_read: len:0, unexpected EOF'. I think this is when I copy/stream large files. But as mentioned only occasionally

I've never seen:
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43380 / cmd: AFP_LISTEXTATTR
Aug 3 08:33:59 tuck afpd[41962]: AFP Replay Cache match: id: 43381 / cmd: AFP_LISTEXTATTR


Since these messages pop up accessing the disks, are your drives Ok (no SMART, ZFS errors) - just asking.

Alexander

 

[joshnerl]

I decided to take the older mac offline and the messages seem to be a lot less frequent. It's been acting funny lately and I'm thinking there could be a OS reinstall in it's future. It's the "kids" computer and there's no telling what kind of abuse it's been taking. It's the same computer that kept needing to recreate it's Time Machine backup.

seggerman - to your question, i'm still trying to figure out how to setup SMART tests in FN, but the stoplight tells me that the volumes are OK. I'm starting to think it's not the freeness box at all.

 

[Paul Muller]

I'm having the same problem after complete re-install. A potential solution provided here, but I'm fairly confident that I've enabled AppleDouble, so somewhat confused!

http://forum.phaseone.com/En/viewtopic.php?f=40&t=12204