netatalk / Bugs / #499 OS X Unable to Hold Connection to Netatalk 3.0.2

Ralph Böhme - 2013-03-08

Works for me.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Ralph Böhme - 2013-03-08

status: open --> pending

milestone: -->
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

thebeck - 2013-03-08

Thank you for looking into this. I think below is the relevant part of my log file. AFP commands come in just fine, but when the AFP_CLOSEVOL comes in, netatalk disconnects. Is there something that I am missing?

Mar 06 21:05:15.574445 afpd[1831] {afp_dsi.c:609} (D5:DSI): DSI request ID: 8
Mar 06 21:05:15.574774 afpd[1831] {afp_dsi.c:624} (D5:AFPDaemon): <== Start AFP command: AFP_OPENVOL
Mar 06 21:05:16.699619 afpd[1831] {afp_dsi.c:631} (D5:AFPDaemon): ==> Finished AFP command: AFP_OPENVOL -> AFP_OK
Mar 06 21:05:16.844369 afpd[1831] {afp_dsi.c:609} (D5:DSI): DSI request ID: 9
Mar 06 21:05:16.844697 afpd[1831] {afp_dsi.c:624} (D5:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Mar 06 21:05:16.848240 afpd[1831] {afp_dsi.c:631} (D5:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Mar 06 21:05:16.855116 afpd[1831] {afp_dsi.c:609} (D5:DSI): DSI request ID: 10
Mar 06 21:05:16.855443 afpd[1831] {afp_dsi.c:624} (D5:AFPDaemon): <== Start AFP command: AFP_CLOSEVOL
Mar 06 21:05:16.855849 afpd[1831] {cnid_dbd.c:494} (D5:CNID): closing database connection for volume '/mnt/HD_a2/Time_Capsule/MacBook_Pro_2010'
Mar 06 21:05:16.856420 afpd[1831] {afp_dsi.c:631} (D5:AFPDaemon): ==> Finished AFP command: AFP_CLOSEVOL -> AFP_OK
Mar 06 21:05:16.856792 afpd[1831] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 10, len: 0): START
Mar 06 21:05:16.857123 afpd[1831] {dsi_stream.c:508} (D10:DSI): dsi_stream_send(0 bytes): START
Mar 06 21:05:16.857450 afpd[1831] {dsi_stream.c:516} (D10:DSI): dsi_stream_send(16 bytes): DSI header, no data
Mar 06 21:05:16.857773 afpd[1831] {dsi_stream.c:283} (D10:DSI): dsi_stream_write(send: 16 bytes): START
Mar 06 21:05:16.858148 afpd[1831] {dsi_stream.c:327} (D10:DSI): dsi_stream_write(send: 16 bytes): END
Mar 06 21:05:16.858486 afpd[1831] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 10, len: 0): END
Mar 06 21:05:16.858809 afpd[1831] {dsi_stream.c:579} (D10:DSI): dsi_stream_receive: START
Mar 06 21:05:16.859134 afpd[1831] {dsi_stream.c:206} (D10:DSI): dsi_buffered_stream_read: 16 bytes
Mar 06 21:05:16.859468 afpd[1831] {dsi_stream.c:150} (D10:DSI): from_buf: 16 bytes
Mar 06 21:05:16.859894 afpd[1831] {dsi_stream.c:164} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Mar 06 21:05:16.860230 afpd[1831] {dsi_stream.c:464} (D10:DSI): dsi_stream_read(16 bytes)
Mar 06 21:05:16.860554 afpd[1831] {dsi_stream.c:181} (D10:DSI): buf_read(16 bytes)
Mar 06 21:05:16.860879 afpd[1831] {dsi_stream.c:150} (D10:DSI): from_buf: 16 bytes
Mar 06 21:05:16.861219 afpd[1831] {dsi_stream.c:164} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Mar 06 21:05:16.861661 cnid_dbd[1834] {comm.c:209} (D10:CNID): comm_rcv: got data on fd 6
Mar 06 21:05:17.852258 afpd[1831] {socket.c:122} (D5:AFPDaemon): select timeout 1 s
Mar 06 21:05:17.852639 afpd[1831] {dsi_stream.c:192} (D10:DSI): buf_read(16 bytes): got: -1
Mar 06 21:05:17.853036 afpd[1831] {dsi_stream.c:483} (E:DSI): dsi_stream_read: len:-1, No such file or directory
Mar 06 21:05:17.853373 afpd[1831] {dsi_stream.c:261} (N:DSI): dsi_disconnect: entering disconnected state
Mar 06 21:06:15.562383 afpd[1831] {afp_dsi.c:311} (D10:AFPDaemon): alarm: tickles: 1, flags: -|-|-|-|DSI_DISCONNECTED|-|-|-|-
Mar 06 21:06:45.572392 afpd[1831] {afp_dsi.c:311} (D10:AFPDaemon): alarm: tickles: 2, flags: -|-|-|-|DSI_DISCONNECTED|-|-|-|-
Mar 06 21:07:15.582416 afpd[1831] {afp_dsi.c:311} (D10:AFPDaemon): alarm: tickles: 3, flags: -|-|-|-|DSI_DISCONNECTED|-|-|-|-

Last edit: thebeck 2013-03-08

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

thebeck - 2013-03-12

Just to test, I redirected another MacBook Pro (OS X 10.6.8, so different OS version) to this netatalk 3.0.2 share. Exact same issue as before. Log file attached.

In the AFP_CLOSEVOL event, my dsi_cmdreply sequence seems to end in an error:
Mar 12 01:58:40.606161 afpd[6086] {socket.c:122} (D5:AFPDaemon): select timeout 1 s
Mar 12 01:58:40.606541 afpd[6086] {dsi_stream.c:192} (D10:DSI): buf_read(16 bytes): got: -1
Mar 12 01:58:40.606937 afpd[6086] {dsi_stream.c:483} (E:DSI): dsi_stream_read: len:-1, No such file or directory
Mar 12 01:58:40.607274 afpd[6086] {dsi_stream.c:261} (N:DSI): dsi_disconnect: entering disconnected state

I looked at some other examples of successful log files (e.g., http://pbox.ca/1daqe), and this is what I see as a correct dsi_cmdreply:
Jan 06 15:52:07.777164 afpd[14308] {socket.c:120} (D5:AFPDaemon): select timeout 1 s
Jan 06 15:52:07.777217 afpd[14308] {dsi_stream.c:190} (D10:DSI): buf_read(16 bytes): got: -1
Jan 06 15:52:07.777246 afpd[14308] {dsi_stream.c:468} (D10:DSI): dsi_stream_read: select read loop
Jan 06 15:52:07.777270 afpd[14308] {dsi_stream.c:179} (D10:DSI): buf_read(16 bytes)
Jan 06 15:52:07.777294 afpd[14308] {dsi_stream.c:148} (D10:DSI): from_buf: 16 bytes

Something is definitely wrong in my situation. Ralph Böhme, are you able to confirm if there is a defect in netatalk 3.0.2 (for my environment)?

Here's some other info:

/proc/cpuinfo

Processor : ARM926EJ-S rev 0 (v5l)
BogoMIPS : 498.07
Features : swp half thumb fastmult edsp
CPU implementer : 0x41
CPU architecture: 5TEJ
CPU variant : 0x0
CPU part : 0x926
CPU revision : 0
Cache type : write-back
Cache clean : cp15 c7 ops
Cache lockdown : format C
Cache format : Harvard
I size : 32768
I assoc : 1
I line length : 32
I sets : 1024
D size : 32768
D assoc : 4
D line length : 32
D sets : 256

Hardware : Feroceon
Revision : 0000
Serial : 0000000000000000

/proc/meminfo

MemTotal: 126836 kB
MemFree: 2300 kB
Buffers: 50112 kB
Cached: 42520 kB
SwapCached: 0 kB
Active: 56472 kB
Inactive: 46304 kB
SwapTotal: 2120416 kB
SwapFree: 2120416 kB
Dirty: 12 kB
Writeback: 0 kB
AnonPages: 10164 kB
Mapped: 6880 kB
Slab: 14368 kB
SReclaimable: 8816 kB
SUnreclaim: 5552 kB
PageTables: 436 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
CommitLimit: 2183832 kB
Committed_AS: 56928 kB
VmallocTotal: 385024 kB
VmallocUsed: 19072 kB
VmallocChunk: 360444 kB

dmesg

Linux version 2.6.22.7 (jack@SWTEST1) (gcc version 3.4.4 (release) (CodeSourcery ARM 2005q3-2)) #4 Fri Jan 22 11:02:54 CST 2010
CPU: ARM926EJ-S [41069260] revision 0 (ARMv5TEJ), cr=00053177
Machine: Feroceon
Using UBoot passing parameters structure
Memory policy: ECC disabled, Data cache writeback
On node 0 totalpages: 32768
DMA zone: 256 pages used for memmap
DMA zone: 0 pages reserved
DMA zone: 32512 pages, LIFO batch:7
Normal zone: 0 pages used for memmap
CPU0: D VIVT write-back cache
CPU0: I cache: 32768 bytes, associativity 1, 32 byte lines, 1024 sets
CPU0: D cache: 32768 bytes, associativity 4, 32 byte lines, 256 sets
Built 1 zonelists. Total pages: 32512
Kernel command line: root=/dev/ram console=ttyS0,115200 :::DB88FXX81:egiga0:none
PID hash table entries: 512 (order: 9, 2048 bytes)
Console: colour dummy device 80x30
Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
Memory: 128MB 0MB 0MB 0MB = 128MB total
Memory: 116736KB available (2876K code, 193K data, 120K init)
Calibrating delay loop... 498.07 BogoMIPS (lpj=2490368)
Mount-cache hash table entries: 512
CPU: Testing write buffer coherency: ok
NET: Registered protocol family 16
Sys Clk = 166666667, Tclk = 166666667

Last edit: thebeck 2013-03-12

afpd.log

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

thebeck - 2013-03-15

Hi Ralph, I downloaded the netatalk 2.2.4 source and compiled natively. Everything is working perfectly with my Time Machine backup under netatalk 2.2.4.

With respect to netatalk 3.0.2, I added a bunch of extra log statements to my netatalk 3.0.2 source to diagnose, but I still can't find the issue as I am not familiar enough with the netatalk source. Do you have any thoughts on the issue? I am happy to add extra log statements on my side based on your guidance. Thanks!

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

thebeck - 2013-11-05

Hello Ralph, et. al.,

With the new netatalk 3.1.0, I tried to move my environment to this new version in the hopes that the issue above was resolved. I would like to inform that I am no longer receiving the issue as described above, and my Time Machine backup seems to be working correctly and smoothly with netatalk 3.1.0

In consideration, please kindly close this issue. If I run into any new issues, I will file a new bug.

Thanks.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Ralph Böhme - 2013-11-05

status: pending --> closed
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Ralph Böhme - 2013-11-05

Thanks for the follow up.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

OS X Unable to Hold Connection to Netatalk 3.0.2

Group

Searches

Help

#499 OS X Unable to Hold Connection to Netatalk 3.0.2

Discussion