mediatomb starts before network comes online

[Phillip Susi]

mediatomb fails to start at boot because the network is not yet up. It's unit file lists After: network-online.target, but this target comes up before NetworkManager has brought the network up. I'm guessing it only counts networks configured in /etc/interfaces.

[Martin Pitt (pitti)]

What's the output of "sudo systemctl status NetworkManager-wait-online.service network-online.target" for you? We do enable this unit by default, so it should wait (this works fine here and for many other people I've talked to).

If they are not running, but enabled, then the reason is that mediatomb is missing "Wants=network-manager.online" (see man systemd.special for details). This needs to be fixed either way.

[Phillip Susi (psusi)]

● NetworkManager-wait-online.service - Network Manager Wait Online
   Loaded: loaded (/lib/systemd/system/NetworkManager-wait-online.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Sun 2015-05-10 22:21:06 EDT; 19h ago
  Process: 1089 ExecStart=/usr/bin/nm-online -s -q --timeout=30 (code=exited, status=0/SUCCESS)
 Main PID: 1089 (code=exited, status=0/SUCCESS)

May 10 22:21:01 faldara systemd[1]: Starting Network Manager Wait Online...
May 10 22:21:06 faldara systemd[1]: Started Network Manager Wait Online.

● network.target - Network
   Loaded: loaded (/lib/systemd/system/network.target; static; vendor preset: enabled)
   Active: active since Sun 2015-05-10 22:21:01 EDT; 19h ago
     Docs: man:systemd.special(7)
           http://www.freedesktop.org/wiki/Software/systemd/NetworkTarget

May 10 22:21:01 faldara systemd[1]: Reached target Network.
May 10 22:21:01 faldara systemd[1]: Starting Network.

mediatomb is After=network-manager.online, are you saying that it *also* has to Wants= it?

The odd thing is that it certainly looks like mediatomb waited for network-manager.online to start.. it tried to start at 22:21:06, which is the same time that nmwo became started. Perhaps there is a race condition and nmwo is actually transitioning to started a fraction of a second before the network is really up?

[Martin Pitt (pitti)]

> mediatomb is After=network-manager.online,

It should certainly be After=network-online.target, I assume that was a typo?

> are you saying that it *also* has to Wants= it?

Yes. After= is purely an ordering of units, it doesn't start one. network-manager.target needs to be Wants= (or Requires=) by an unit who wants to wait for it. You didn't give me the status of network-online.target, but as NetworkManager-wait-online.service actually *did* run, and waited for a nontrivial amount of time (5s) I suppose that network-online.target is also running.

Can you please give me the output of "systemctl status network-manager.online mediatomb.service" to see whether it really started after that?

[Phillip Susi (psusi)]

Yes, it is after NetworkManager-wait-online.service and network.target. It looks like mediatomb did wait for nm-online, yet eth0 is not yet configured ( I inserted a ExecStartPre=ifconfig -a to see in a previous boot ).

● NetworkManager-wait-online.service - Network Manager Wait Online
   Loaded: loaded (/lib/systemd/system/NetworkManager-wait-online.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Sun 2015-05-10 22:21:06 EDT; 1 day 21h ago
  Process: 1089 ExecStart=/usr/bin/nm-online -s -q --timeout=30 (code=exited, status=0/SUCCESS)
 Main PID: 1089 (code=exited, status=0/SUCCESS)

May 10 22:21:01 faldara systemd[1]: Starting Network Manager Wait Online...
May 10 22:21:06 faldara systemd[1]: Started Network Manager Wait Online.

● mediatomb.service - UPnP MediaServer
   Loaded: loaded (/lib/systemd/system/mediatomb.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sun 2015-05-10 22:21:07 EDT; 1 day 21h ago
  Process: 1773 ExecStopPost=/sbin/ifconfig $MT_INTERFACE -allmulti (code=exited, status=0/SUCCESS)
  Process: 1770 ExecStopPost=/sbin/route del -net 239.0.0.0 netmask 255.0.0.0 (code=exited, status=0/SUCCESS)
  Process: 1739 ExecStart=/usr/bin/mediatomb -d -u $MT_USER -g $MT_GROUP -P /run/mediatomb.pid -l $MT_LOGFILE -m $MT_HOME -f $MT_CFGDIR -p $MT_PORT -e $MT_INTERFACE (code=exited, status=0/SUCCESS)
  Process: 1734 ExecStartPre=/sbin/ifconfig $MT_INTERFACE allmulti (code=exited, status=0/SUCCESS)
  Process: 1727 ExecStartPre=/sbin/route add -net 239.0.0.0 netmask 255.0.0.0 $MT_INTERFACE (code=exited, status=0/SUCCESS)
  Process: 1718 ExecStartPre=/bin/grep -q MT_USER /etc/default/mediatomb (code=exited, status=0/SUCCESS)
 Main PID: 1767 (code=exited, status=1/FAILURE)

May 10 22:21:06 faldara systemd[1]: Starting UPnP MediaServer...
May 10 22:21:07 faldara systemd[1]: Started UPnP MediaServer.
May 10 22:21:07 faldara systemd[1]: mediatomb.service: main process exited, code=exited, stat...LURE
May 10 22:21:07 faldara ifconfig[1773]: Warning: Interface eth0 still in ALLMULTI mode.
May 10 22:21:07 faldara systemd[1]: Unit mediatomb.service entered failed state.
May 10 22:21:07 faldara systemd[1]: mediatomb.service failed.

[Martin Pitt (pitti)]

So it looks like NM-wait-online isn't waiting long/hard enough?

[Phillip Susi (psusi)]

It looks that way, yes.

[Tomasz Bakiera (kog)]

To not duplicate with bug, I'm attaching my problem related to mediatomb startup.
My 'interface' file is:

auto lo
iface lo inet loopback

auto eth0
iface eth0 inet dhcp

in /etc/defaults/mediatomb I have line:
MT_INTERFACE="eth0"

After boot I'm checking status of mediatomb, because it doesn't start:

root@alfa-nas:~# systemctl status mediatomb
● mediatomb.service - UPnP MediaServer
   Loaded: loaded (/lib/systemd/system/mediatomb.service; enabled; vendor preset: enabled)
   Active: failed (Result: resources) since czw 2015-06-18 13:54:13 CEST; 1min 17s ago
  Process: 757 ExecStart=/usr/bin/mediatomb -d -u $MT_USER -g $MT_GROUP -P /run/mediatomb.pid -l $MT_LOGFILE -m $MT_HOME -f $MT_CFGDIR -p $MT_PORT -e $MT_INTERFACE (code=exited, status=0/SUCCESS)
  Process: 731 ExecStartPre=/sbin/ifconfig $MT_INTERFACE allmulti (code=exited, status=0/SUCCESS)
  Process: 626 ExecStartPre=/sbin/route add -net 239.0.0.0 netmask 255.0.0.0 $MT_INTERFACE (code=exited, status=7)
  Process: 587 ExecStartPre=/bin/grep -q MT_USER /etc/default/mediatomb (code=exited, status=0/SUCCESS)

cze 18 13:54:09 alfa-nas systemd[1]: Starting UPnP MediaServer...
cze 18 13:54:09 alfa-nas route[626]: SIOCADDRT: Network is down
cze 18 13:54:13 alfa-nas systemd[1]: PID 1171 read from file /run/mediatomb.pid does not exist or is a zombie.
cze 18 13:54:13 alfa-nas systemd[1]: Failed to start UPnP MediaServer.
cze 18 13:54:13 alfa-nas systemd[1]: Unit mediatomb.service entered failed state.
cze 18 13:54:13 alfa-nas systemd[1]: mediatomb.service failed.

Then I'm restarting mediatomb:

root@alfa-nas:~# systemctl restart mediatomb

No errors, so time to check status:

root@alfa-nas:~# systemctl status mediatomb
● mediatomb.service - UPnP MediaServer
   Loaded: loaded (/lib/systemd/system/mediatomb.service; enabled; vendor preset: enabled)
   Active: active (running) since czw 2015-06-18 13:55:55 CEST; 2s ago
  Process: 1738 ExecStart=/usr/bin/mediatomb -d -u $MT_USER -g $MT_GROUP -P /run/mediatomb.pid -l $MT_LOGFILE -m $MT_HOME -f $MT_CFGDIR -p $MT_PORT -e $MT_INTERFACE (code=exited, status=0/SUCCESS)
  Process: 1735 ExecStartPre=/sbin/ifconfig $MT_INTERFACE allmulti (code=exited, status=0/SUCCESS)
  Process: 1731 ExecStartPre=/sbin/route add -net 239.0.0.0 netmask 255.0.0.0 $MT_INTERFACE (code=exited, status=0/SUCCESS)
  Process: 1730 ExecStartPre=/bin/grep -q MT_USER /etc/default/mediatomb (code=exited, status=0/SUCCESS)
 Main PID: 1741 (mediatomb)
   CGroup: /system.slice/mediatomb.service
           └─1741 /usr/bin/mediatomb -d -u mediatomb -g mediatomb -P /run/mediatomb.pid -l /var/log/mediatomb -m /etc -f mediatomb -p 60000 -e...

cze 18 13:55:55 alfa-nas systemd[1]: Starting UPnP MediaServer...
cze 18 13:55:55 alfa-nas systemd[1]: Started UPnP MediaServer.

Regards

Tom

[Phillip Susi (psusi)]

I've done some more investigating and identified the problem; I'm just not sure what the solution is. The problem is that nm decides the network is "up" as soon as there are no interfaces that still have work to be done ( such as obtaining a dhcp lease ). My e1000e interface comes up in the disconnected state, which nm considers to be an unusable state with no work to be done, and so it declares the network to be all set up. I'm not sure why, but it takes another 20 seconds for the e1000e to auto negotiate the 100 mbps link speed with my router, and then the link transitions to up, and nm starts trying to get a dhcp lease.

I suppose I'm still wondering why it takes so long for the link to come up, but I guess the real problem is the fact that nm will consider networking to be up so long as there is no link yet. I'm thinking it needs patched to not consider the network up until at least one interface is actually functioning.

Another possible fix is for mediatomb and any other services that depend on "network" to instead depend on "<email address hidden>".