Netatalk 4.0 - Future-proofing Apple File Sharing

[rdmark]

If options aren't taking effect, a common cause is that netatalk is reading afp.conf from a different location. Run "netatalk -V" and compare the path to afp.conf with what you're editing.

 

[bribri]

@rdmark It's definitely using the right file. My current afp.conf:

[Global]
uam list = uams_guest.so
guest account = username
log level = default:debug
log file = /opt/local/var/log/netatalk4.log
extmap file = /opt/local/etc/extmap.conf

[Stuff2]
volume name = Stuff2
path = /Users/username/misc/afp
file perm = 0644
directory perm = 0755
ea = sys
legacy volume size = yes

I tried changing the volume name just to confirm that it was picking up those changes, and indeed it was.

 

[scj312]

@rdmark Unfortunately, I seem to be stuck in a restart loop once again:

I'll increase log levels so that next time we have something more useful to work with.

With the debug logging, unfortunately I don't see much of note when the error occurs that initiates the first restart:

Apr 13 07:10:14.761241 afpd[74] {volume.c:316} (debug:AFPDaemon): getvolparams: Volume 'Files'
Apr 13 07:10:14.761280 afpd[74] {ad_conv.c:298} (debug:end_of_list_marker): ad_convert("/mnt/afpshare"): BEGIN
Apr 13 07:10:14.761296 afpd[74] {ad_conv.c:316} (debug:end_of_list_marker): ad_convert("/mnt/afpshare"): END: 0
Apr 13 07:10:14.761316 afpd[74] {ad_open.c:2043} (debug:end_of_list_marker): ad_open("/mnt/afpshare", 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)]
Apr 13 07:10:14.761334 afpd[74] {ad_open.c:1239} (debug:end_of_list_marker): ad_open_hf_ea("/mnt/afpshare", HF|DIR|O_RDWR|O_CREAT): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 13 07:10:14.761346 afpd[74] {ad_open.c:1269} (debug:end_of_list_marker): ad_open_hf_ea("/mnt/afpshare"): opening base file for meta adouble EA
Apr 13 07:10:14.761393 afpd[74] {ad_open.c:1331} (debug:end_of_list_marker): ad_open_hf_ea("/mnt/afpshare", HF|DIR|O_RDWR|O_CREAT): END: 0 [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 13 07:10:14.761423 afpd[74] {ad_open.c:2106} (debug:end_of_list_marker): ad_open("/mnt/afpshare"): END: 0 {d: 0, m: 1, r: 0}[dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 13 07:10:14.761448 afpd[74] {ad_flush.c:464} (debug:end_of_list_marker): ad_close(HF): BEGIN: {d: 0, m: 1, r: 0} [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 13 07:10:14.761470 afpd[74] {ad_flush.c:527} (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)]
Apr 13 07:10:21.068315 afpd[37] {main.c:548} (error:AFPDaemon): main: asp_getsession: Resource busy
Apr 13 07:10:21.071394 netatalk[36] {netatalk.c:219} (info:Default): child[37]: exited 1
Apr 13 07:10:21.183585 netatalk[36] {netatalk.c:255} (note:AFPDaemon): Restarting 'afpd' (restarts: 1)

Each time the service restarts, I see similar log entries to before:

Apr 13 07:10:27.385284 afpd[195] {afp_config.c:217} (note:AFPDaemon): Pluto:AFPServer@* started on 420.113:149 (4.2.0)
Apr 13 07:10:27.385331 afpd[195] {afp_config.c:232} (debug:AFPDaemon): DSIConfigInit: hostname: Pluto, listen: -, interfaces: enp3s0, port: 548
Apr 13 07:10:27.386237 afpd[195] {dsi_tcp.c:363} (info:DSI): dsi_tcp_init: bind: Address in use

Apr 13 07:10:27.386258 afpd[195] {dsi_tcp.c:473} (error:DSI): No suitable network config for TCP socket
Apr 13 07:10:27.386337 afpd[195] {dsi_tcp.c:363} (info:DSI): dsi_tcp_init: bind: Address in use

Apr 13 07:10:27.386354 afpd[195] {dsi_tcp.c:473} (error:DSI): No suitable network config for TCP socket
Apr 13 07:10:27.386442 afpd[195] {dsi_tcp.c:363} (info:DSI): dsi_tcp_init: bind: Address in use

Apr 13 07:10:27.386460 afpd[195] {dsi_tcp.c:473} (error:DSI): No suitable network config for TCP socket
Apr 13 07:10:27.386549 afpd[195] {dsi_tcp.c:363} (info:DSI): dsi_tcp_init: bind: Address in use

Apr 13 07:10:27.386564 afpd[195] {dsi_tcp.c:473} (error:DSI): No suitable network config for TCP socket
Apr 13 07:10:27.386600 afpd[195] {afp_config.c:324} (error:Default): no suitable network address found, use "afp listen" or "afp interfaces"
Apr 13 07:10:27.386627 afpd[195] {main.c:359} (error:AFPDaemon): main: no servers configured
Apr 13 07:10:27.387413 netatalk[36] {netatalk.c:219} (info:Default): child[195]: exited 2
Apr 13 07:10:28.184288 netatalk[36] {netatalk.c:255} (note:AFPDaemon): Restarting 'afpd' (restarts: 2)

I set log level = default:debug afpdaemon:debug uamsdaemon:debug. Are there other parameters I should be setting to help troubleshoot?

 

[NJRoadfan]

Disable AppleTalk and see if the problem still occurs. The "asp_getsession" error is from afpd not initializing AppleTalk sockets correctly. The best I can tell is something is clobbering the NIC in the container so that it appears "busy/unavailable" whenever a device tries to bind and open a socket on it.

 

[NJRoadfan]

I'm seeing references to a host called "saturn" in your past nbplkup queries sharing the same AppleTalk address as Pluto. Is there more then one docker container running netatalk or is the host itself running netatalk? That would case binding errors as the container can't open up listening ports on a network interface if another process is using them. This appears to be happening with AppleTalk and TCP/IP.

 

[scj312]

Disable AppleTalk and see if the problem still occurs. The "asp_getsession" error is from afpd not initializing AppleTalk sockets correctly. The best I can tell is something is clobbering the NIC in the container so that it appears "busy/unavailable" whenever a device tries to bind and open a socket on it.

Unfortunately, without AppleTalk, netatalk isn't of much use to me I'd be willing to test this for a bit, but unfortunately this issue is a bit unpredictable--sometimes it occurs within a day or two, other times it takes weeks.

I'm seeing references to a host called "saturn" in your past nbplkup queries sharing the same AppleTalk address as Pluto. Is there more then one docker container running netatalk or is the host itself running netatalk? That would case binding errors as the container can't open up listening ports on a network interface if another process is using them. This appears to be happening with AppleTalk and TCP/IP.

Ah, that naming issue was due to a misconfiguration at the time. I only have one instance of netatalk running.

 

[NJRoadfan]

Is there anything else AppleTalk/DDP running on that machine/interface? I'm not too familiar with Docker, does it's NIC passthru use the host's MAC? This behavior is certainly odd.

The other possibility is that you are running out of listening sockets. How many connections are being made to this machine at once? The default is 200, which should be more then enough for a hobby server.