#499 OS X Unable to Hold Connection to Netatalk 3.0.2

None
closed
nobody
None
1
2013-11-05
2013-03-06
thebeck
No

Hello, I am running into an issue whereby my Mac OS X 10.8.2 cannot hold onto an AFP connection to netatalk 3.0.2. I am running netatalk 3.0.2 on a DLink DNS-343. It was built natively -- no issues during make. Attached is a PDF of the error on my Mac, afp.conf, afpd.log, and the configure/make log. Please advise if this is a defect or an issue with my configuration.

1 Attachments

Discussion

  • Ralph Böhme
    Ralph Böhme
    2013-03-08

    Works for me.

     
  • Ralph Böhme
    Ralph Böhme
    2013-03-08

    • status: open --> pending
    • milestone: -->
     
  • thebeck
    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
  • thebeck
    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
    Attachments
  • thebeck
    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!

     
  • thebeck
    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.

     
  • Ralph Böhme
    Ralph Böhme
    2013-11-05

    • status: pending --> closed
     
  • Ralph Böhme
    Ralph Böhme
    2013-11-05

    Thanks for the follow up.