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.

 

[scj312]

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.

Netatalk is the only thing running on that machine using DDP (unless something is hiding ). As for the MAC, AFAICT the host MAC is used. I have jrouter running on another machine and it reports the host's MAC for Netatalk's DDP address.

Is the sockets number you are referring to host-wide, or specific to Netatalk? I do have a ton of stuff running on this machine! However, what makes me think this may be an issue with Netatalk, or how it is managing restarting its services, is that a simple restart of the container fixes the problem (until the next occurrence)--no other changes to the host are required for things to work normally again.

 

[NJRoadfan]

The sockets thing would be how many sockets Netatalk, specifically afpd, has open (both listening and active clients). The "resource not available" message points to the DDP listening socket (128) somehow becoming unavailable, which is triggering afpd to restart. Somehow after the restart, it can't open up a listening socket on TCP port 541 anymore either! The only other thing I can think of is some sort of security policy to being triggered by the Netatalk container shutting down the ability for services to open listening sockets.

 

[scj312]

The sockets thing would be how many sockets Netatalk, specifically afpd, has open (both listening and active clients). The "resource not available" message points to the DDP listening socket (128) somehow becoming unavailable, which is triggering afpd to restart. Somehow after the restart, it can't open up a listening socket on TCP port 541 anymore either! The only other thing I can think of is some sort of security policy to being triggered by the Netatalk container shutting down the ability for services to open listening sockets.

Ah! I wonder if something is not quite right with the afpd restart process--my Mac (modern, using TCP/IP) never disconnects from the mounted AFP share when this happens, and it can continue to read and write from the share during the restart loop (however, if I unmount, then I cannot reconnect). So maybe the port is actually still open, rather than a policy blocking it.

 

[NJRoadfan]

afpd forks child processes to service a client, that's why you are able to maintain a connection. The child process continues to work fine, but if you try to reconnect or connect new clients, the main process won't respond because it is unable to open up TCP port 541 to listen for new connections. I'm betting if you restart one of the other AppleTalk services after this happens, they too won't be able to open a port.

Also what distro are you running as the host's OS? Part of me suspects that the kernel level driver for Docker's "host" networking is the source of this problem.

 

[NJRoadfan]

When the container is in this weird state, can you attempt to startup python's built in web server in the container and see if it binds to a listening port? Also check that you can connect to it from a machine on your network.

 

[rdmark]

Easter update: over the last few days, I have containerized both the mysql CNID backend as well as the netatalk webmin module.

As a quick recap, netatalk uses a berkeleydb CNID backend by default presently. However the mysql backend allows for better control and scalability, while also being a living technology unlike bdb which has been abandoned for many years at this point.

However, mysql/mariadb is a bit more cumbersome since you have to install and configure database server software. It isn't particularly hard, but not plug'n'play either.

Anyways, by combining the docker compose yaml examples that I have compiled, you can now create a container constellation like below: netatalk running with a mariadb backend, webmin as the web UI for netatalk and adminer as the web UI for mariadb.

The main purpose for all this, personally, is testing. These are all running in continuous integration now. I don't want to inadvertently break the mysql backend again. But this can potentially be used in a "production" deployment as well. Not guarantees though!

[+] Running 7/7

 ✔ Network netatalk_default                                            Created                                      0.1s
 ✔ Volume "netatalk_cnid_db_data"                                      Created                                      0.0s
 ✔ Container netatalk-adminer-1                                        Created                                      0.1s
 ✔ Container netatalk-mariadb-1                                        Created                                      0.1s
 ✔ Container netatalk-webmin-1                                         Created                                      0.0s
 ✔ Container netatalk-netatalk-1                                       Recreated                                   10.2s