atftpd won't start on opensuse tumbleweed under systemd

Question

I tried installing atftpd today.

The package installed successfully:

# zypper se atftp
Loading repository data...
Reading installed packages...

S | Name  | Summary                         | Type   
--+-------+---------------------------------+--------
i | atftp | Advanced TFTP Server and Client | package

But the service did not start after installation.

# service atftpd start
Job for atftpd.service failed. See "systemctl status atftpd.service" and "journalctl -xn" for details.
# journalctl -xn
-- Logs begin at Thu 2015-03-05 22:21:19 CET, end at Fri 2015-03-13 22:45:01 CET. --
Mar 13 22:43:13 server systemd[1]: Configuration file /usr/lib/systemd/system/atftpd.service is marked executable. Please remove executable permission bits. Proceeding anyway.
[...]

I removed the execution flag and got rid of the error message, but the service still won't start.

# chmod -x /usr/lib/systemd/system/atftpd.service
# service atftpd start
Job for atftpd.service failed. See "systemctl status atftpd.service" and "journalctl -xn" for details.

Looking at the systemd service definition file everything looks rather straight forward:

# cat /usr/lib/systemd/system/atftpd.service
[Unit]
Description=Advanced TFTP Server

[Service]
EnvironmentFile=/etc/sysconfig/atftpd
ExecStart=/usr/sbin/atftpd --user $ATFTPD_USER --group $ATFTPD_GROUP $ATFTPD_OPTIONS $ATFTPD_DIRECTORY
StandardInput=socket

And the environment file seem to define valid values for all the variables:

# grep ^ATFT /etc/sysconfig/atftpd
ATFTPD_USER="tftp"
ATFTPD_GROUP="tftp"
ATFTPD_OPTIONS="--daemon --logfile /var/log/atftpd/atftp.log"
ATFTPD_USE_INETD="no"
ATFTPD_DIRECTORY="/srv/tftpboot"
ATFTPD_BIND_ADDRESSES=""

Manually running the commands successfully starts the daemon:

# systemctl start atftpd.service
Job for atftpd.service failed. See "systemctl status atftpd.service" and "journalctl -xn" for details.
# ps aux | grep tftp[d]
# source /etc/sysconfig/atftpd 
# /usr/sbin/atftpd --user $ATFTPD_USER --group $ATFTPD_GROUP $ATFTPD_OPTIONS $ATFTPD_DIRECTORY
# ps aux | grep tftp[d]
tftp      1907  0.0  0.0  11596   152 ?        Ss   23:18   0:00 /usr/sbin/atftpd --user tftp --group tftp --daemon --logfile /var/log/atftpd/atftp.log /srv/tftpboot

As I am new to atftpd, suse tumbleweed and systemd I don't really know what might be wrong. I've set the --daemon and --logfile explicitly in $AFTPD_OPTIONS, but according to the config file help text that should be the default anyway.

The diagnostics text in full:

# systemctl start atftpd.service
Job for atftpd.service failed. See "systemctl status atftpd.service" and "journalctl -xn" for details.
# systemctl status atftpd.service
atftpd.service - Advanced TFTP Server
   Loaded: loaded (/usr/lib/systemd/system/atftpd.service; static)
   Active: failed (Result: resources)

Mar 13 22:59:55 server systemd[1]: atftpd.service failed to run 'start' task: Invalid argument
# journalctl -xn
-- Logs begin at Thu 2015-03-05 22:21:19 CET, end at Fri 2015-03-13 23:33:13 CET. --
Mar 13 23:25:38 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:98:d6:bb:20:90:a2:86:dd SRC=fe80:0000:0000:0000:189b:b08a:4ad3:89bf DST=ff02:0000:0000:0000:00
Mar 13 23:28:00 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:f0:24:75:e4:6e:54:86:dd SRC=fe80:0000:0000:0000:1c6a:034e:81fc:bb59 DST=ff02:0000:0000:0000:00
Mar 13 23:28:15 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:f0:24:75:e4:6e:54:86:dd SRC=fe80:0000:0000:0000:1c6a:034e:81fc:bb59 DST=ff02:0000:0000:0000:00
Mar 13 23:29:43 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:1c:ab:a7:98:9c:80:86:dd SRC=fe80:0000:0000:0000:00d4:2bc4:7bd3:85f3 DST=ff02:0000:0000:0000:00
Mar 13 23:30:01 server cron[1912]: pam_unix(crond:session): session opened for user root by (uid=0)
Mar 13 23:30:01 server systemd[1913]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Mar 13 23:30:01 server CRON[1912]: pam_unix(crond:session): session closed for user root
Mar 13 23:33:10 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:6c:40:08:ae:e7:3a:86:dd SRC=fe80:0000:0000:0000:6e40:08ff:feae:e73a DST=ff02:0000:0000:0000:00
Mar 13 23:33:11 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:b4:18:d1:dd:52:cc:86:dd SRC=fe80:0000:0000:0000:b618:d1ff:fedd:52cc DST=ff02:0000:0000:0000:00
Mar 13 23:33:13 server kernel: SFW2-INext-DROP-DEFLT IN=ens32 OUT= MAC=33:33:00:00:00:fb:6c:40:08:ae:e7:3a:86:dd SRC=fe80:0000:0000:0000:6e40:08ff:feae:e73a DST=ff02:0000:0000:0000:00

Why does the service refuse to start? What can I do to fix it?

EDIT:

Really good answer by @jdebp, thanks!

To follow up I can verify that the server does start as expected after reverting my tweaks to the config file. It still won't work, but it does start. ;)

Server side

$ sudo systemctl status atftpd.{socket,service}                                                                                                                        
atftpd.socket - Advanced tftp Server Activation Socket
   Loaded: loaded (/usr/lib/systemd/system/atftpd.socket; disabled)
   Active: active (running) since Mon 2015-03-16 14:45:50 CET; 5h 19min ago
   Listen: [::]:69 (Datagram)


atftpd.service - Advanced TFTP Server
   Loaded: loaded (/usr/lib/systemd/system/atftpd.service; static)
   Active: active (running) since Mon 2015-03-16 20:04:49 CET; 16s ago
 Main PID: 3337 (atftpd)
   CGroup: /system.slice/atftpd.service
           └─3337 /usr/sbin/atftpd --user tftp --group tftp /srv/tftpboot

Mar 16 20:04:49 server atftpd[3337]: connect: Address family not supported by protocol
Mar 16 20:04:54 server atftpd[3337]: connect: Address family not supported by protocol
Mar 16 20:04:59 server atftpd[3337]: connect: Address family not supported by protocol
Mar 16 20:05:04 server atftpd[3337]: connect: Address family not supported by protocol

Client side

$ atftp --trace --verbose -l nvidia-bug-report.log.gz -p server 69
Trace mode on.
Verbose mode on.
sent WRQ <file: nvidia-bug-report.log.gz, mode: octet <>>
timeout: retrying...
sent WRQ <file: nvidia-bug-report.log.gz, mode: octet <>>
timeout: retrying...
sent WRQ <file: nvidia-bug-report.log.gz, mode: octet <>>
timeout: retrying...
sent WRQ <file: nvidia-bug-report.log.gz, mode: octet <>>
timeout: retrying...
tftp: aborting

EDIT2:

Forcing the daemon to use ipv4 made the file transfer successful.

> grep 0\.0 /etc/sysconfig/atftpd /usr/lib/systemd/system/atftpd.socket
/etc/sysconfig/atftpd:ATFTPD_BIND_ADDRESSES="0.0.0.0"
/usr/lib/systemd/system/atftpd.socket:ListenDatagram=0.0.0.0:69

Solution

Why does the service refuse to start? What can I do to fix it?

Because you're starting the wrong thing. Start the right thing. ☺

The giveaway here is

StandardInput=socket

The answer is that, whilst others on the WWW (several years ago) have done it differently, the (more recent) OpenSUSE packaging for atftpd runs atftpd as a fully-fledged socket-activated service. There's a lot written about socket activation in systemd. It is subtle, and explaining it is beyond the scope of this answer. The thing that you need to know about this particular service, here and now, is this:

You, the system administrator, do not start/stop your atftpd service by starting/stopping the service unit. You start/stop the socket unit. When the socket is up, systemd monitors it, and traffic to the socket will cause systemd itself to start the service unit, connecting the service to the socket that activated it.

So systemctl start atftpd.socket and systemctl stop atftpd.socket are the commands here. (The same with enable and disable of course.) Also use systemctl status atftpd.{service,socket} to see the status of both the socket and service units.

(You'll notice that the atftpd.service file has no

[Install]

atftpd.socket

socket

By the way, the contents of your /etc/sysconfig/atftpd file are bogus. They don't match the atftpd.sysconfig that is in OpenSUSE. The OpenSUSE one matches what systemd has been told about the dæmon. Your local modifications are unnecessary in one case and outright wrong in the other.

Your systemd service unit is defaulting to Type=simple but your /etc/sysconfig/atftpd is using the --daemon option. That is a readiness protocol mismatch. Readiness protocol mismatches cause services not to start correctly, or (more usually) to be (mis-)diagnosed by systemd as failing. So you would still have a problem, of your own making, even when you switched to controlling the socket unit instead of the service unit. Remove the --daemon option that you added in. Your dæmon should not be forking-and-exiting to indicate readiness. It's a fully-fledged socket-activated service in OpenSUSE. The as-shipped file is right.

Similarly, systemd will already record all output to syslog, standard output, and standard error by the dæmon; and you are already accessing that journal with the journalctl comand. It is unnecessary to use --logfile and set up a duplicate logging system.