Transfering large files fails

[ronangaillard]

Describe the bug
When moving a large file (tried with a 842k file) from the hard drive to the shared folder it fails and disconnect from the shared drive.
If I move files around 200k it works fine.

I tried to set tickleval = 600 but it did not change anything (apart from failing later).

For information the transfer failed after 5 minutes and 15 seconds. The transfer speed seems very bad too, not sure why.

Here is the log I have on the netatalk side :

Dec 12 01:00:11.202087 afpd[61] {dsi_tcp.c:238} (info:DSI): AFP/TCP session from 192.168.1.12:2048
Dec 12 01:00:11.252691 afpd[23] {main.c:178} (info:AFPDaemon): child[61]: done
Dec 12 01:00:14.096343 afpd[62] {dsi_tcp.c:238} (info:DSI): AFP/TCP session from 192.168.1.12:2049
Dec 12 01:00:14.154146 afpd[62] {uams_randnum.c:306} (info:ad): randnum/rand2num login: ronan
Dec 12 01:00:14.227197 afpd[62] {auth.c:245} (note:AFPDaemon): Login by ronan (AFP2.2)
Dec 12 01:02:44.228089 afpd[62] {afp_dsi.c:326} (error:AFPDaemon): afp_alarm: child timed out, entering disconnected state
Dec 12 01:02:44.228106 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Dec 12 01:02:44.228145 afpd[62] {afp_dsi.c:685} (error:AFPDaemon): dsi_wrtreply: Bad file descriptor
Dec 12 01:02:44.228151 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Dec 12 01:02:44.228157 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state

I tried
To Reproduce
Move file more then 800k from hard drive to the shared drive.

Expected behavior
To not fail

Environment

• Server OS: Linux Tower 6.1.49-Unraid based on Unicode 7.0.0 #1 SMP PREEMPT_DYNAMIC Wed Aug 30 09:42:35 PDT 2023 x86_64 Intel(R) Core(TM) i5-8500 CPU @ 3.00GHz GenuineIntel GNU/Linux
• Client OS: Macintosh SE/30, 68MB RAM, System 7.5.3
• Netatalk Version 4.0.8

Logs

Dec 12 01:00:11.202087 afpd[61] {dsi_tcp.c:238} (info:DSI): AFP/TCP session from 192.168.1.12:2048
Dec 12 01:00:11.252691 afpd[23] {main.c:178} (info:AFPDaemon): child[61]: done
Dec 12 01:00:14.096343 afpd[62] {dsi_tcp.c:238} (info:DSI): AFP/TCP session from 192.168.1.12:2049
Dec 12 01:00:14.154146 afpd[62] {uams_randnum.c:306} (info:ad): randnum/rand2num login: ronan
Dec 12 01:00:14.227197 afpd[62] {auth.c:245} (note:AFPDaemon): Login by ronan (AFP2.2)
Dec 12 01:02:44.228089 afpd[62] {afp_dsi.c:326} (error:AFPDaemon): afp_alarm: child timed out, entering disconnected state
Dec 12 01:02:44.228106 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Dec 12 01:02:44.228145 afpd[62] {afp_dsi.c:685} (error:AFPDaemon): dsi_wrtreply: Bad file descriptor
Dec 12 01:02:44.228151 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Dec 12 01:02:44.228157 afpd[62] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state

[ronangaillard]

After some more investigations it seems like the closed down connection happens even with no file transfer. After a few minutes after system booted I always get this message.

[NJRoadfan]

This is almost certainly because the client or server is not seeing DSI "tickle" packets. Once a DSI connection is established, both the client and server send these out periodically to verify that the link is still alive.

A network trace will determine which side is not working (logs points to server not seeing client tickle). How is the SE/30 connected to the network? PDS Ethernet? SCSI Ethernet?

[ronangaillard]

It is connected using BlueSCSI DaynaPort emulation through SCSI.

What is the best way to get network trace for this ? Wireshark, mitm, ... ?

[NJRoadfan]

What build options were used to compile? I know that if --with-debugging=true is set, tickles are disabled on the server.

First test would be Wireshark (use filter dsi) or tcpdump and see if there is any DSI tickle packets on the network at all. We know the BlueSCSI is communicating since it can see and login to the server. These are directed packets, so Wireshark or any other packet sniffer needs to be running directly on the server to intercept.

[rdmark]

Can you please share your afp.conf? It is helpful to know your exact settings.

The tickleval and timeout options are only supposed to be used for debugging, BTW. They may cause non-compliant behavior.

[rdmark]

@ronangaillard Did you have the chance to look at this yet? If we can get some debug logs, we should be able to get some insights into the movement of DSI tickles.

[cgervais]

I've been having the same issue connecting from Mac OS 9.2.1 running under UTM 4.6.4 (a QEMU wrapper) when attempting to write a file to a network share of almost any size. The Finder gets to 3K of and then just craps out, but it appears the copy process is still running because a blob of bytes is deposited onto the server but cannot be read usefully.

I have a physical device, a PowerMac 7100/80 running Mac OS 9.1 connected via Ethernet, that I will test out as well.

I'm running Netatalk 4.0.8 on a Raspberry Pi that I compile and install locally. It's connected to an ethernet hub, which in turn, is connected to one of my Eeros. In terms of obtaining the debug logs, is it a compile-time or run-time option to generate those?

[cgervais]

OK, I figured out logging! Here's an example of trying to copy a PDF file, NetworkingOpenTransport.pdf, from my emulated Mac OS 9.2.1 to the AppleShare directory, which is just the root of my home directory. Please let me know if you want a more detailed debug log level or what else would be helpful.

Jan 02 21:17:30.134943 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.134997 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.135106 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.135220 afpd[3406] {ofork.c:253} (debug:AFPDaemon): of_stat('/home/cgervais/NetworkingOpenTransport.pdf': No such file or directory)
Jan 02 21:17:30.135283 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.135350 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:2, f/d:073f/133f) {cwdid:2, cwd: /home/cgervais, name:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.135410 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFPERR_NOOBJ
Jan 02 21:17:30.135469 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 145, len: 0): START
Jan 02 21:17:30.135583 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 145, len: 0): END
Jan 02 21:17:30.135651 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.135717 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.162757 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.162868 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 14
Jan 02 21:17:30.162925 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 146
Jan 02 21:17:30.163014 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 02 21:17:30.163096 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.163154 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.163212 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.163288 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'.'}
Jan 02 21:17:30.163349 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:2, f/d:077f/137f) {cwdid:2, cwd: /home/cgervais, name:'.'}
Jan 02 21:17:30.163410 afpd[3406] {ofork.c:301} (debug:AFPDaemon): of_statdir: stating: '../cgervais'
Jan 02 21:17:30.163502 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.163577 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.163689 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): END: 0 [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.163760 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/."): END: 0 {d: 0, m: 1, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.163823 afpd[3406] {directory.c:1321} (debug:AFPDaemon): metadata('.'):     Parent DID: 1
Jan 02 21:17:30.163882 afpd[3406] {directory.c:1375} (debug:AFPDaemon): metadata('.'):            DID: 2
Jan 02 21:17:30.163979 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.164057 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.164121 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.164180 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 146, len: 84): START
Jan 02 21:17:30.164299 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 146, len: 84): END
Jan 02 21:17:30.164417 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.164495 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.172563 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.172639 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 14
Jan 02 21:17:30.172706 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 147
Jan 02 21:17:30.172762 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 02 21:17:30.172818 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.172876 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.172935 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.173045 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'.'}
Jan 02 21:17:30.173148 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:2, f/d:077f/137f) {cwdid:2, cwd: /home/cgervais, name:'.'}
Jan 02 21:17:30.173211 afpd[3406] {ofork.c:301} (debug:AFPDaemon): of_statdir: stating: '../cgervais'
Jan 02 21:17:30.173299 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173373 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173485 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): END: 0 [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173559 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/."): END: 0 {d: 0, m: 1, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173626 afpd[3406] {directory.c:1321} (debug:AFPDaemon): metadata('.'):     Parent DID: 1
Jan 02 21:17:30.173687 afpd[3406] {directory.c:1375} (debug:AFPDaemon): metadata('.'):            DID: 2
Jan 02 21:17:30.173782 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173844 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.173903 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.173964 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 147, len: 84): START
Jan 02 21:17:30.174080 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 147, len: 84): END
Jan 02 21:17:30.174148 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.174222 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.194879 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.194987 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 29
Jan 02 21:17:30.195047 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 148
Jan 02 21:17:30.195103 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 02 21:17:30.195159 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 1): START
Jan 02 21:17:30.195217 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 1): RESULT: pdid: 0, path: "ROOT_PARENT"
Jan 02 21:17:30.195294 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.195417 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'.'}
Jan 02 21:17:30.195483 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:1, f/d:073f/133f) {cwdid:2, cwd: /home/cgervais, name:'.'}
Jan 02 21:17:30.195544 afpd[3406] {ofork.c:301} (debug:AFPDaemon): of_statdir: stating: '../cgervais'
Jan 02 21:17:30.195631 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.195705 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.195814 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/.", HF|DIR|O_RDONLY): END: 0 [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.195889 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/."): END: 0 {d: 0, m: 1, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.195951 afpd[3406] {directory.c:1321} (debug:AFPDaemon): metadata('.'):     Parent DID: 1
Jan 02 21:17:30.196011 afpd[3406] {directory.c:1375} (debug:AFPDaemon): metadata('.'):            DID: 2
Jan 02 21:17:30.196099 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.196172 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.196234 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.196292 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 148, len: 66): START
Jan 02 21:17:30.196422 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 148, len: 66): END
Jan 02 21:17:30.196490 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.196556 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.211692 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.211802 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 37
Jan 02 21:17:30.211860 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 149
Jan 02 21:17:30.211920 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_CREATEFILE
Jan 02 21:17:30.211978 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.212033 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.212091 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.212202 afpd[3406] {ofork.c:253} (debug:AFPDaemon): of_stat('/home/cgervais/NetworkingOpenTransport.pdf': No such file or directory)
Jan 02 21:17:30.212265 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.212345 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.212422 afpd[3406] {ad_open.c:1002} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.212797 afpd[3406] {ad_open.c:1068} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.212937 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL): BEGIN [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.213107 afpd[3406] {ad_open.c:766} (debug:end_of_list_marker): ad_header_read_ea: No data available
Jan 02 21:17:30.213173 afpd[3406] {ad_open.c:1264} (debug:end_of_list_marker): ad_open_hf_ea("NetworkingOpenTransport.pdf"): creating metadata EA
Jan 02 21:17:30.213231 afpd[3406] {ad_open.c:367} (debug:end_of_list_marker): new_ad_header("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.213332 afpd[3406] {ad_flush.c:406} (debug:end_of_list_marker): ad_flush(DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL)
Jan 02 21:17:30.213392 afpd[3406] {ad_flush.c:280} (debug:end_of_list_marker): ad_flush_hf(DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL)
Jan 02 21:17:30.213447 afpd[3406] {ad_flush.c:109} (debug:end_of_list_marker): ad_rebuild_adouble_header_ea
Jan 02 21:17:30.213784 afpd[3406] {ad_open.c:1276} (debug:end_of_list_marker): ad_open_hf_ea("NetworkingOpenTransport.pdf"): created metadata EA
Jan 02 21:17:30.213864 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.213955 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL): END: 0 [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.214033 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 1, m: 1, r: 0}[dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.214127 afpd[3406] {cnid_dbd.c:569} (debug:CNID): cnid_dbd_add: CNID: 2, name: 'NetworkingOpenTransport.pdf', dev: 0xb302, inode: 0x8d5, type: file
Jan 02 21:17:30.214440 cnid_dbd[3416] {dbd_add.c:148} (debug:CNID): dbd_add(did:2, 'NetworkingOpenTransport.pdf', dev/ino:0xb302/0x8d5) {start}
Jan 02 21:17:30.214733 cnid_dbd[3416] {dbd_lookup.c:200} (debug:CNID): dbd_lookup: name: 'NetworkingOpenTransport.pdf', did: 2, dev/ino: 0xb302/0x8d5 is not in the CNID database
Jan 02 21:17:30.214809 cnid_dbd[3416] {dbd_add.c:164} (debug:CNID): dbd_add(did:2, 'NetworkingOpenTransport.pdf', dev/ino:0xb302/0x8d5): {adding to database ...}
Jan 02 21:17:30.216273 cnid_dbd[3416] {dbd_add.c:193} (debug:CNID): dbd_add(did:2, 'NetworkingOpenTransport.pdf', dev/ino:0xb302/0x8d5): Added with CNID: 9809
Jan 02 21:17:30.216655 afpd[3406] {cnid_dbd.c:581} (debug:CNID): cnid_dbd_add: got CNID: 9809
Jan 02 21:17:30.216800 afpd[3406] {ad_flush.c:406} (debug:end_of_list_marker): ad_flush(DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL)
Jan 02 21:17:30.216878 afpd[3406] {ad_flush.c:280} (debug:end_of_list_marker): ad_flush_hf(DF|HF|NOHF|O_RDWR|O_CREAT|O_EXCL)
Jan 02 21:17:30.216935 afpd[3406] {ad_flush.c:109} (debug:end_of_list_marker): ad_rebuild_adouble_header_ea
Jan 02 21:17:30.217183 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(DF|HF): BEGIN: {d: 1, m: 1, r: 0} [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.217283 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(DF|HF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.217356 afpd[3406] {fce_api.c:550} (debug:Spotlight): register_fce(path: /home/cgervais/NetworkingOpenTransport.pdf, event: FCE_FILE_CREATE)
Jan 02 21:17:30.217556 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_CREATEFILE -> AFP_OK
Jan 02 21:17:30.217627 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 149, len: 0): START
Jan 02 21:17:30.217730 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 149, len: 0): END
Jan 02 21:17:30.217795 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.217864 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.226480 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 0
Jan 02 21:17:30.226685 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.226871 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 16, unread:6 , space left: 12582890): returning 16
Jan 02 21:17:30.226941 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 6
Jan 02 21:17:30.226998 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 6
Jan 02 21:17:30.227055 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 150
Jan 02 21:17:30.227112 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETVOLPARAM
Jan 02 21:17:30.227182 afpd[3406] {volume.c:312} (debug:AFPDaemon): getvolparams: Volume 'cgervais's home'
Jan 02 21:17:30.227236 afpd[3406] {ad_conv.c:287} (debug:end_of_list_marker): ad_convert("/home/cgervais"): BEGIN
Jan 02 21:17:30.227310 afpd[3406] {ad_conv.c:65} (debug:end_of_list_marker): ad_conv_v22ea_hf("/home/cgervais"): BEGIN
Jan 02 21:17:30.227387 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais", HF|DIR|O_RDWR): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227455 afpd[3406] {ad_open.c:1088} (debug:end_of_list_marker): ad_open_hf_v2("/home/cgervais", HF|DIR|O_RDWR): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227515 afpd[3406] {ad_open.c:1112} (debug:end_of_list_marker): ad_open_hf_v2("/home/cgervais"): open flags: O_RDWR
Jan 02 21:17:30.227613 afpd[3406] {ad_open.c:1200} (debug:end_of_list_marker): ad_open_hf_v2("/home/cgervais", HF|DIR|O_RDWR): END: -1 [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227677 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais"): END: -1 {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227743 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF|SHRMD): BEGIN: {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227823 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(DF|HF|SHRMD): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227887 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF|SHRMD): BEGIN: {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.227954 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(DF|HF|SHRMD): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228011 afpd[3406] {ad_conv.c:126} (debug:end_of_list_marker): ad_conv_v22ea_hf("/home/cgervais"): END: -1
Jan 02 21:17:30.228070 afpd[3406] {ad_conv.c:201} (debug:end_of_list_marker): ad_conv_v22ea_hf("/home/cgervais"): deleting adouble:v2 file: "/home/cgervais/.AppleDouble/.Parent"
Jan 02 21:17:30.228154 afpd[3406] {ad_conv.c:237} (debug:end_of_list_marker): ad_conv_dehex("/home/cgervais"): BEGIN
Jan 02 21:17:30.228212 afpd[3406] {ad_conv.c:305} (debug:end_of_list_marker): ad_convert("/home/cgervais"): END: 0
Jan 02 21:17:30.228279 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais", HF|DIR|O_RDWR|O_CREAT): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228346 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais", HF|DIR|O_RDWR|O_CREAT): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228402 afpd[3406] {ad_open.c:1245} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais"): opening base file for meta adouble EA
Jan 02 21:17:30.228551 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais", HF|DIR|O_RDWR|O_CREAT): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228622 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais"): END: 0 {d: 0, m: 1, r: 0}[dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228767 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228847 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(HF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.228909 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETVOLPARAM -> AFP_OK
Jan 02 21:17:30.228970 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 150, len: 18): START
Jan 02 21:17:30.229105 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 150, len: 18): END
Jan 02 21:17:30.229176 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.229248 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.237914 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.238134 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 41
Jan 02 21:17:30.238202 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 151
Jan 02 21:17:30.238262 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 02 21:17:30.238322 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.238377 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.238436 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.238545 afpd[3406] {directory.c:1049} (debug:AFPDaemon): cname('/home/cgervais'): {file: 'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.238604 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.238669 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:2, f/d:073f/133f) {cwdid:2, cwd: /home/cgervais, name:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.238725 afpd[3406] {file.c:613} (debug:AFPDaemon): getfilparams("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.238808 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", HF|OF|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.238889 afpd[3406] {ad_open.c:1002} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.239000 afpd[3406] {ad_open.c:1068} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.239073 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.239170 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.239252 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.239319 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 4): BEGIN
Jan 02 21:17:30.239402 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 1, m: 1, r: 0}[dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.239460 afpd[3406] {file.c:287} (debug:AFPDaemon): getmetadata("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.239567 afpd[3406] {dircache.c:381} (debug:AFPDaemon): dircache_search_by_name(did:2, "NetworkingOpenTransport.pdf")
Jan 02 21:17:30.239626 afpd[3406] {dircache.c:414} (debug:AFPDaemon): dircache(did:2,"NetworkingOpenTransport.pdf"): {not in cache}
Jan 02 21:17:30.239696 afpd[3406] {cnid_dbd.c:569} (debug:CNID): cnid_dbd_add: CNID: 2, name: 'NetworkingOpenTransport.pdf', dev: 0xb302, inode: 0x8d5, type: file
Jan 02 21:17:30.240589 cnid_dbd[3416] {dbd_add.c:148} (debug:CNID): dbd_add(did:2, 'NetworkingOpenTransport.pdf', dev/ino:0xb302/0x8d5) {start}
Jan 02 21:17:30.240968 cnid_dbd[3416] {dbd_lookup.c:249} (debug:CNID): dbd_lookup(DID:2/'NetworkingOpenTransport.pdf',0xb302/0x8d5): Got CNID: 9809
Jan 02 21:17:30.241050 cnid_dbd[3416] {dbd_add.c:160} (debug:CNID): dbd_add: dbd_lookup success --> CNID: 9809
Jan 02 21:17:30.241312 afpd[3406] {cnid_dbd.c:581} (debug:CNID): cnid_dbd_add: got CNID: 9809
Jan 02 21:17:30.241393 afpd[3406] {file.c:306} (debug:AFPDaemon): getmetadata: caching: did:2, "NetworkingOpenTransport.pdf", cnid:9809
Jan 02 21:17:30.241507 afpd[3406] {dircache.c:490} (debug:AFPDaemon): dircache(did:9809,'NetworkingOpenTransport.pdf'): {added}
Jan 02 21:17:30.241575 afpd[3406] {file.c:376} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'): AFP Attributes: 0000
Jan 02 21:17:30.241633 afpd[3406] {file.c:383} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):     Parent DID: 2
Jan 02 21:17:30.241700 afpd[3406] {file.c:431} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):           CNID: 9809
Jan 02 21:17:30.241769 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF|OF): BEGIN: {d: 1, m: 1, r: 0} [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.241875 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(DF|HF|OF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.241938 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.241999 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 151, len: 68): START
Jan 02 21:17:30.242124 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 151, len: 68): END
Jan 02 21:17:30.242190 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.242258 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.253134 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.253370 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 86
Jan 02 21:17:30.253436 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 152
Jan 02 21:17:30.253499 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_SETFLDRPARAM
Jan 02 21:17:30.253557 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.253615 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.253675 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.253788 afpd[3406] {directory.c:1049} (debug:AFPDaemon): cname('/home/cgervais'): {file: 'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.253853 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.253993 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.254073 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.254190 afpd[3406] {ad_open.c:1245} (debug:end_of_list_marker): ad_open_hf_ea("NetworkingOpenTransport.pdf"): opening base file for meta adouble EA
Jan 02 21:17:30.254330 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.254414 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.254489 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 0, m: 1, r: 0}[dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.254704 afpd[3406] {ad_flush.c:406} (debug:end_of_list_marker): ad_flush(HF|O_RDWR|O_CREAT)
Jan 02 21:17:30.254778 afpd[3406] {ad_flush.c:280} (debug:end_of_list_marker): ad_flush_hf(HF|O_RDWR|O_CREAT)
Jan 02 21:17:30.254837 afpd[3406] {ad_flush.c:109} (debug:end_of_list_marker): ad_rebuild_adouble_header_ea
Jan 02 21:17:30.255014 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.255101 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(HF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.255217 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_SETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.255282 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 152, len: 0): START
Jan 02 21:17:30.255424 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 152, len: 0): END
Jan 02 21:17:30.255493 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.255564 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.265782 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.266023 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 41
Jan 02 21:17:30.266092 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 153
Jan 02 21:17:30.266152 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 02 21:17:30.266213 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.266269 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.266330 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.266449 afpd[3406] {directory.c:1049} (debug:AFPDaemon): cname('/home/cgervais'): {file: 'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.266513 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.266583 afpd[3406] {filedir.c:81} (debug:AFPDaemon): getfildirparams(vid:1, did:2, f/d:073f/133f) {cwdid:2, cwd: /home/cgervais, name:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.266641 afpd[3406] {file.c:613} (debug:AFPDaemon): getfilparams("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.266747 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", HF|OF|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.266826 afpd[3406] {ad_open.c:1002} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.266935 afpd[3406] {ad_open.c:1068} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.267010 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.267168 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.267260 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.267330 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 4): BEGIN
Jan 02 21:17:30.267415 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 1, m: 1, r: 0}[dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.267475 afpd[3406] {file.c:287} (debug:AFPDaemon): getmetadata("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.267534 afpd[3406] {dircache.c:381} (debug:AFPDaemon): dircache_search_by_name(did:2, "NetworkingOpenTransport.pdf")
Jan 02 21:17:30.267616 afpd[3406] {dircache.c:410} (debug:AFPDaemon): dircache(did:2,"NetworkingOpenTransport.pdf"): {found in cache}
Jan 02 21:17:30.267678 afpd[3406] {file.c:376} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'): AFP Attributes: 0000
Jan 02 21:17:30.267738 afpd[3406] {file.c:383} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):     Parent DID: 2
Jan 02 21:17:30.267802 afpd[3406] {file.c:431} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):           CNID: 9809
Jan 02 21:17:30.267872 afpd[3406] {ad_flush.c:446} (debug:end_of_list_marker): ad_close(HF|OF): BEGIN: {d: 1, m: 1, r: 0} [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.267982 afpd[3406] {ad_flush.c:509} (debug:end_of_list_marker): ad_close(DF|HF|OF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.268045 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 02 21:17:30.268107 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 153, len: 68): START
Jan 02 21:17:30.268218 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 153, len: 68): END
Jan 02 21:17:30.268285 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.268360 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.282334 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.282510 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 41
Jan 02 21:17:30.282581 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 154
Jan 02 21:17:30.282641 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_OPENFORK
Jan 02 21:17:30.282702 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.282758 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.282820 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.282934 afpd[3406] {directory.c:1049} (debug:AFPDaemon): cname('/home/cgervais'): {file: 'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.283095 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.283246 afpd[3406] {fork.c:353} (debug:AFPDaemon): afp_openfork("/home/cgervais/NetworkingOpenTransport.pdf", data, O_RDWR)
Jan 02 21:17:30.283347 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", DF|SHRMD|O_RDWR): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283422 afpd[3406] {ad_open.c:1002} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|SHRMD|O_RDWR): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283583 afpd[3406] {ad_open.c:1068} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|SHRMD|O_RDWR): END: 0 [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283653 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 1, m: 0, r: 0}[dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283725 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN {d: 1, m: 0, r: 0}[dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283797 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN [dfd: 11 (ref: 1), mfd: 11 (ref: 1), rfd: -1 (ref: 0)]
Jan 02 21:17:30.283897 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.283979 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): END: 0 [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.284047 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 1, m: 1, r: 0}[dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.284106 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.284160 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.284234 afpd[3406] {file.c:287} (debug:AFPDaemon): getmetadata("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.284293 afpd[3406] {dircache.c:381} (debug:AFPDaemon): dircache_search_by_name(did:2, "NetworkingOpenTransport.pdf")
Jan 02 21:17:30.284369 afpd[3406] {dircache.c:410} (debug:AFPDaemon): dircache(did:2,"NetworkingOpenTransport.pdf"): {found in cache}
Jan 02 21:17:30.284427 afpd[3406] {file.c:383} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):     Parent DID: 2
Jan 02 21:17:30.284485 afpd[3406] {file.c:431} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):           CNID: 9809
Jan 02 21:17:30.284553 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(data, off: 9223372036854775799 (OPEN_RD_DATA): BEGIN
Jan 02 21:17:30.284616 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.284683 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.284739 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(data, off: 9223372036854775803 (DENY_RD_DATA): BEGIN
Jan 02 21:17:30.284799 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775803 (DENY_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.284858 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.284917 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(data, RD|FILELOCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.284979 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.285052 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.285111 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(data, RD|FILELOCK, off: 9223372036854775803 (DENY_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.285173 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775803 (DENY_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.285237 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.285329 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(data, off: 9223372036854775798 (OPEN_WR_DATA): BEGIN
Jan 02 21:17:30.285391 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285451 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.285504 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(data, off: 9223372036854775802 (DENY_WR_DATA): BEGIN
Jan 02 21:17:30.285563 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775802 (DENY_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285623 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.285681 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(data, RD|FILELOCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285744 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285806 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.285865 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(data, RD|FILELOCK, off: 9223372036854775802 (DENY_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285925 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775802 (DENY_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.285988 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.286049 afpd[3406] {fork.c:492} (debug:AFPDaemon): afp_openfork("/home/cgervais/NetworkingOpenTransport.pdf"): fork: 2
Jan 02 21:17:30.286108 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_OPENFORK -> AFP_OK
Jan 02 21:17:30.286166 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 154, len: 46): START
Jan 02 21:17:30.286305 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 154, len: 46): END
Jan 02 21:17:30.286376 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.286448 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.299181 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.299343 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 41
Jan 02 21:17:30.299386 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 155
Jan 02 21:17:30.299421 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_OPENFORK
Jan 02 21:17:30.299459 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.299494 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.299532 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.299613 afpd[3406] {directory.c:1049} (debug:AFPDaemon): cname('/home/cgervais'): {file: 'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.299649 afpd[3406] {directory.c:1112} (debug:AFPDaemon): cname('/home/cgervais') {end: curdir:'/home/cgervais', path:'NetworkingOpenTransport.pdf'}
Jan 02 21:17:30.299725 afpd[3406] {fork.c:353} (debug:AFPDaemon): afp_openfork("/home/cgervais/NetworkingOpenTransport.pdf", reso, O_RDWR)
Jan 02 21:17:30.299773 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", RF|SHRMD|O_RDWR|O_CREAT): BEGIN {d: 1, m: 1, r: 0}[dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.299819 afpd[3406] {ad_open.c:1002} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|RF|SHRMD|O_RDWR|O_CREAT): BEGIN [dfd: 11 (ref: 2), mfd: 11 (ref: 2), rfd: -1 (ref: 0)]
Jan 02 21:17:30.299863 afpd[3406] {ad_open.c:1068} (debug:end_of_list_marker): ad_open_df("/home/cgervais/NetworkingOpenTransport.pdf", DF|RF|SHRMD|O_RDWR|O_CREAT): END: 0 [dfd: 11 (ref: 3), mfd: 11 (ref: 3), rfd: -1 (ref: 0)]
Jan 02 21:17:30.299943 afpd[3406] {ad_open.c:1401} (debug:end_of_list_marker): ad_open_rf("/home/cgervais/NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.300163 afpd[3406] {ad_open.c:1479} (debug:end_of_list_marker): ad_open_rf("NetworkingOpenTransport.pdf"): created adouble rfork: "._NetworkingOpenTransport.pdf"
Jan 02 21:17:30.300235 afpd[3406] {ad_open.c:1493} (debug:end_of_list_marker): ad_open_rf("NetworkingOpenTransport.pdf"): created adouble rfork, initializing: "._NetworkingOpenTransport.pdf"
Jan 02 21:17:30.300270 afpd[3406] {ad_open.c:367} (debug:end_of_list_marker): new_ad_header("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.300317 afpd[3406] {ad_open.c:1496} (debug:end_of_list_marker): ad_open_rf("NetworkingOpenTransport.pdf"): created adouble rfork, flushing: "._NetworkingOpenTransport.pdf"
Jan 02 21:17:30.300353 afpd[3406] {ad_flush.c:406} (debug:end_of_list_marker): ad_flush(DF|SHRMD|O_RDWR)
Jan 02 21:17:30.300389 afpd[3406] {ad_flush.c:280} (debug:end_of_list_marker): ad_flush_hf(DF|SHRMD|O_RDWR)
Jan 02 21:17:30.300421 afpd[3406] {ad_flush.c:109} (debug:end_of_list_marker): ad_rebuild_adouble_header_ea
Jan 02 21:17:30.300529 afpd[3406] {ad_flush.c:382} (debug:end_of_list_marker): ad_flush_rf(DF|SHRMD|O_RDWR)
Jan 02 21:17:30.300569 afpd[3406] {ad_flush.c:157} (debug:end_of_list_marker): ad_rebuild_adouble_header_osx
Jan 02 21:17:30.300665 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.300710 afpd[3406] {ad_open.c:1361} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): size: 2129648016
Jan 02 21:17:30.300748 afpd[3406] {ad_open.c:1527} (debug:end_of_list_marker): ad_open_rf("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0
Jan 02 21:17:30.300791 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 2, m: 1, r: 1}[dfd: 11 (ref: 3), mfd: 11 (ref: 3), rfd: 12 (ref: 1)]
Jan 02 21:17:30.300848 afpd[3406] {ad_open.c:1977} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN {d: 2, m: 1, r: 1}[dfd: 11 (ref: 3), mfd: 11 (ref: 3), rfd: 12 (ref: 1)]
Jan 02 21:17:30.300891 afpd[3406] {ad_open.c:1215} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): BEGIN [dfd: 11 (ref: 3), mfd: 11 (ref: 3), rfd: 12 (ref: 1)]
Jan 02 21:17:30.300942 afpd[3406] {ad_open.c:1337} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): BEGIN
Jan 02 21:17:30.300984 afpd[3406] {ad_open.c:1361} (debug:end_of_list_marker): ad_reso_size("NetworkingOpenTransport.pdf"): size: 1995155640
Jan 02 21:17:30.301025 afpd[3406] {ad_open.c:1289} (debug:end_of_list_marker): ad_open_hf_ea("/home/cgervais/NetworkingOpenTransport.pdf", HF|O_RDWR|O_CREAT): END: 0 [dfd: 11 (ref: 4), mfd: 11 (ref: 4), rfd: 12 (ref: 1)]
Jan 02 21:17:30.301068 afpd[3406] {ad_open.c:2040} (debug:end_of_list_marker): ad_open("/home/cgervais/NetworkingOpenTransport.pdf"): END: 0 {d: 2, m: 2, r: 1}[dfd: 11 (ref: 4), mfd: 11 (ref: 4), rfd: 12 (ref: 1)]
Jan 02 21:17:30.301103 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.301136 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.301180 afpd[3406] {file.c:287} (debug:AFPDaemon): getmetadata("NetworkingOpenTransport.pdf")
Jan 02 21:17:30.301217 afpd[3406] {dircache.c:381} (debug:AFPDaemon): dircache_search_by_name(did:2, "NetworkingOpenTransport.pdf")
Jan 02 21:17:30.301261 afpd[3406] {dircache.c:410} (debug:AFPDaemon): dircache(did:2,"NetworkingOpenTransport.pdf"): {found in cache}
Jan 02 21:17:30.301295 afpd[3406] {file.c:383} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):     Parent DID: 2
Jan 02 21:17:30.301329 afpd[3406] {file.c:431} (debug:AFPDaemon): metadata('NetworkingOpenTransport.pdf'):           CNID: 9809
Jan 02 21:17:30.301389 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(reso, off: 9223372036854775799 (OPEN_RD_DATA): BEGIN
Jan 02 21:17:30.301429 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775801 (OPEN_RD_RSRC), len: 1): BEGIN
Jan 02 21:17:30.301471 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.301504 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(reso, off: 9223372036854775803 (DENY_RD_DATA): BEGIN
Jan 02 21:17:30.301539 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775805 (DENY_RD_RSRC), len: 1): BEGIN
Jan 02 21:17:30.301574 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.301611 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(reso, RD|FILELOCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.301648 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775801 (OPEN_RD_RSRC), len: 1): BEGIN
Jan 02 21:17:30.301692 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.301727 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(reso, RD|FILELOCK, off: 9223372036854775803 (DENY_RD_DATA), len: 1): BEGIN
Jan 02 21:17:30.301763 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775805 (DENY_RD_RSRC), len: 1): BEGIN
Jan 02 21:17:30.301802 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.301836 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(reso, off: 9223372036854775798 (OPEN_WR_DATA): BEGIN
Jan 02 21:17:30.301871 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775800 (OPEN_WR_RSRC), len: 1): BEGIN
Jan 02 21:17:30.301906 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.301938 afpd[3406] {ad_lock.c:600} (debug:end_of_list_marker): ad_testlock(reso, off: 9223372036854775802 (DENY_WR_DATA): BEGIN
Jan 02 21:17:30.301974 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_GETLK, F_WRLCK, off: 9223372036854775804 (DENY_WR_RSRC), len: 1): BEGIN
Jan 02 21:17:30.302009 afpd[3406] {ad_lock.c:613} (debug:end_of_list_marker): ad_testlock: END: 0
Jan 02 21:17:30.302048 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(reso, RD|FILELOCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.302085 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775800 (OPEN_WR_RSRC), len: 1): BEGIN
Jan 02 21:17:30.302124 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.302158 afpd[3406] {ad_lock.c:363} (debug:end_of_list_marker): ad_lock(reso, RD|FILELOCK, off: 9223372036854775802 (DENY_WR_DATA), len: 1): BEGIN
Jan 02 21:17:30.302195 afpd[3406] {ad_lock.c:66} (debug:end_of_list_marker): set_lock(fd: 11, F_SETLK, F_RDLCK, off: 9223372036854775804 (DENY_WR_RSRC), len: 1): BEGIN
Jan 02 21:17:30.302233 afpd[3406] {ad_lock.c:498} (debug:end_of_list_marker): ad_lock: END: 0
Jan 02 21:17:30.302269 afpd[3406] {fork.c:492} (debug:AFPDaemon): afp_openfork("/home/cgervais/NetworkingOpenTransport.pdf"): fork: 3
Jan 02 21:17:30.302304 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_OPENFORK -> AFP_OK
Jan 02 21:17:30.302342 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 155, len: 46): START
Jan 02 21:17:30.302418 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 155, len: 46): END
Jan 02 21:17:30.302460 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.302504 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.312742 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.312863 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 10
Jan 02 21:17:30.312906 afpd[3406] {afp_dsi.c:606} (debug:DSI): DSI request ID: 156
Jan 02 21:17:30.312946 afpd[3406] {afp_dsi.c:621} (debug:AFPDaemon): <== Start AFP command: AFP_SETFORKPARAM
Jan 02 21:17:30.313041 afpd[3406] {directory.c:471} (debug:AFPDaemon): dirlookup(did: 2): START
Jan 02 21:17:30.313094 afpd[3406] {directory.c:620} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/home/cgervais"
Jan 02 21:17:30.313135 afpd[3406] {directory.c:1143} (debug:AFPDaemon): movecwd(to: did: 2, "/home/cgervais")
Jan 02 21:17:30.313292 afpd[3406] {afp_dsi.c:629} (debug:AFPDaemon): ==> Finished AFP command: AFP_SETFORKPARAM -> AFP_OK
Jan 02 21:17:30.313593 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 156, len: 0): START
Jan 02 21:17:30.313759 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 156, len: 0): END
Jan 02 21:17:30.313818 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.313868 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.324715 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.324871 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 12
Jan 02 21:17:30.324910 afpd[3406] {afp_dsi.c:664} (debug:AFPDaemon): <== Start AFP command: AFP_WRITE
Jan 02 21:17:30.324951 afpd[3406] {fork.c:1179} (debug:AFPDaemon): afp_write(fork: 2 [data], off: 0, size: 2048)
Jan 02 21:17:30.325011 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.325060 afpd[3406] {fork.c:1118} (debug:AFPDaemon): write_file(off: 0, size: 2048)
Jan 02 21:17:30.325101 afpd[3406] {ad_write.c:62} (debug:end_of_list_marker): ad_write: off: 0, size: 2048, eabuflen: 1995090028
Jan 02 21:17:30.325225 afpd[3406] {fork.c:1318} (debug:AFPDaemon): afp_write: wrote: 2048, offset: 0
Jan 02 21:17:30.325265 afpd[3406] {afp_dsi.c:674} (debug:AFPDaemon): ==> Finished AFP command: AFP_WRITE -> AFP_OK
Jan 02 21:17:30.325301 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 157, len: 4): START
Jan 02 21:17:30.325404 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 157, len: 4): END
Jan 02 21:17:30.325447 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.325487 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.334936 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:17:30.335026 afpd[3406] {dsi_stream.c:638} (debug:DSI): dsi_stream_receive: DSI cmdlen: 12
Jan 02 21:17:30.335064 afpd[3406] {afp_dsi.c:664} (debug:AFPDaemon): <== Start AFP command: AFP_WRITE
Jan 02 21:17:30.335103 afpd[3406] {fork.c:1179} (debug:AFPDaemon): afp_write(fork: 2 [data], off: 2048, size: 98304)
Jan 02 21:17:30.335143 afpd[3406] {dsi_stream.c:161} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jan 02 21:18:01.933204 afpd[3406] {afp_dsi.c:333} (debug:AFPDaemon): afp_alarm: sending DSI tickle
Jan 02 21:18:31.933290 afpd[3406] {afp_dsi.c:333} (debug:AFPDaemon): afp_alarm: sending DSI tickle
Jan 02 21:19:01.933376 afpd[3406] {afp_dsi.c:333} (debug:AFPDaemon): afp_alarm: sending DSI tickle
Jan 02 21:19:31.933407 afpd[3406] {afp_dsi.c:326} (error:AFPDaemon): afp_alarm: child timed out, entering disconnected state
Jan 02 21:19:31.933688 afpd[3406] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Jan 02 21:19:31.933962 afpd[3406] {socket.c:151} (debug:AFPDaemon): select: Bad file descriptor
Jan 02 21:19:31.934117 afpd[3406] {afp_dsi.c:674} (debug:AFPDaemon): ==> Finished AFP command: AFP_WRITE -> AFP_OK
Jan 02 21:19:31.934182 afpd[3406] {dsi_cmdreply.c:23} (debug:DSI): dsi_cmdreply(DSI ID: 158, len: 4): START
Jan 02 21:19:31.934240 afpd[3406] {dsi_cmdreply.c:32} (debug:DSI): dsi_cmdreply(DSI ID: 158, len: 4): END
Jan 02 21:19:31.934300 afpd[3406] {afp_dsi.c:685} (error:AFPDaemon): dsi_wrtreply: Bad file descriptor
Jan 02 21:19:31.934355 afpd[3406] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Jan 02 21:19:31.934414 afpd[3406] {dsi_stream.c:259} (note:DSI): dsi_disconnect: entering disconnected state
Jan 02 21:19:31.934473 afpd[3406] {server_ipc.c:318} (debug:AFPDaemon): ipc_child_write(IPC_STATE)
Jan 02 21:19:31.934632 afpd[3393] {main.c:503} (debug:AFPDaemon): main: IPC request from child[3406]
Jan 02 21:19:31.934729 afpd[3393] {server_ipc.c:230} (debug:AFPDaemon): ipc_server_read(IPC_STATE): pid: 3406

[cgervais]

Some follow up FWIW:

1. I tested connecting to 4.0.8 from my physical PowerMac and was able to transfer large files without any issues
2. I built and deployed the latest 4.0.10 code and am not seeing the issue when transferring large files from my UTM/QEMU VM
3. The above finding could be a coincidence, so I'll do more testing but I was able to repeatedly move around my large-ish test file that would previously fail

[rdmark]

@cgervais So if I understand the situation correctly, you had the issue consistently in your environment before, but after reinstalling netatalk it works?

[cgervais]

@cgervais So if I understand the situation correctly, you had the issue consistently in your environment before, but after reinstalling netatalk it works?

After building and deploying the latest 4.1.0 code, the problem seems to have gone away. I'll keep testing and if something changes with supporting large file transfers, will add more here. I mistakenly cited a non-existent 4.0.10 version above.

[rdmark]

@ronangaillard Did you have a chance to follow up on the last few suggestions? In particular, like NJRoadfan says, to make sure you haven't inadvertently enabled debug mode that turns off the DSI tickles.

Please also try the latest netatalk version, and make sure you build the release profile.