Bug 11102 - systemd thinks network.service failed when it worked
Summary: systemd thinks network.service failed when it worked
Status: RESOLVED OLD
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: Cauldron
Hardware: All Linux
Priority: Normal normal
Target Milestone: ---
Assignee: Colin Guthrie
QA Contact:
URL:
Whiteboard: MGA5TOO
Keywords: Triaged
Depends on:
Blocks:
 
Reported: 2013-08-28 20:20 CEST by Frank Griffin
Modified: 2017-03-25 06:49 CET (History)
3 users (show)

See Also:
Source RPM: systemd
CVE:
Status comment:


Attachments

Description Frank Griffin 2013-08-28 20:20:58 CEST
If you do a non-graphical boot of cauldron, you will see that systemd repeated reports failure of the network service and restarts it.

The problem appears to be that ifplugd tries to muck with squid, and sets a non-zero exit status if squid isn't running.  Not sure whether the network.service should be ignoring this, or whether ifplugd should be checking for a running squid or ignoring the error:

[root@ftgme2 ftg]# systemctl status network
network.service - LSB: Bring up/down networking
   Loaded: loaded (/etc/rc.d/init.d/network)
   Active: failed (Result: exit-code) since Wed 2013-08-28 13:44:19 EDT; 29min ago
  Process: 2403 ExecStart=/etc/rc.d/init.d/network start (code=exited, status=1/FAILURE)
   CGroup: /system.slice/network.service
           ââ2537 /sbin/ifplugd -I -b -i enp2s0
           ââ2939 dhclient -1 -q -lf /var/lib/dhclient/dhclient--enp2s0.leas...

Aug 28 13:44:23 ftgme2 dhclient[2731]: DHCPREQUEST on enp2s0 to 255.255.255...7
Aug 28 13:44:23 ftgme2 dhclient[2731]: DHCPACK from 192.168.3.101
Aug 28 13:44:24 ftgme2 dhclient[2731]: bound to 192.168.3.102 -- renewal in....
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client: Determining IP inform....
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client: 192.168.3.102
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client: squid.service - LSB: ...n
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client:    Loaded: loaded (/e...)
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client:    Active: inactive (...)
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: client: squid: ERROR: No runn...y
Aug 28 13:44:24 ftgme2 ifplugd(enp2s0)[2537]: Program executed successfully.
[root@ftgme2 ftg]# 


Reproducible: 

Steps to Reproduce:
Manuel Hiebel 2013-08-28 21:16:20 CEST

Keywords: (none) => Triaged
Assignee: bugsquad => mageia

Comment 1 Florian Hubold 2013-12-07 09:00:11 CET
Also present in Mageia 3, and without squid:

systemctl status network.service
network.service - LSB: Bring up/down networking
          Loaded: loaded (/etc/rc.d/init.d/network)
          Active: failed (Result: exit-code) since Tue, 2013-12-03 16:27:54 CET; 3 days ago
         Process: 1210 ExecStart=/etc/rc.d/init.d/network start (code=exited, status=1/FAILURE)
          CGroup: name=systemd:/system/network.service
                  â 1401 /usr/sbin/wpa_supplicant -B -i wlan0 -c /etc/wpa_supplicant.conf -D wext
                  â 1403 /sbin/ifplugd -I -b -i wlan0
                  â 4094 dhclient -1 -q -lf /var/lib/dhclient/dhclient--wlan0.lease -pf /var/run/dhclient...

Dec 04 19:26:51 Mageia3 ifplugd(wlan0)[1403]: Link beat lost.
Dec 04 19:26:57 Mageia3 ifplugd(wlan0)[1403]: Executing '/etc/ifplugd/ifplugd.action wlan0 down'.
Dec 04 19:26:57 Mageia3 ifplugd(wlan0)[1403]: Program executed successfully.
Dec 04 19:27:15 Mageia3 ifplugd(wlan0)[1403]: Link beat detected.
Dec 04 19:27:16 Mageia3 ifplugd(wlan0)[1403]: Executing '/etc/ifplugd/ifplugd.action wlan0 up'.
Dec 04 19:27:17 Mageia3 dhclient[3974]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Dec 04 19:27:17 Mageia3 dhclient[3974]: DHCPACK from 192.168.178.1
Dec 04 19:27:18 Mageia3 dhclient[3974]: bound to 192.168.178.20 -- renewal in 340019 seconds.
Dec 04 19:27:18 Mageia3 ifplugd(wlan0)[1403]: client: Determining IP information for wlan0... done.
Dec 04 19:27:18 Mageia3 ifplugd(wlan0)[1403]: Program executed successfully.


Weird thing is, can't see the reason for that status "Active: failed (Result: exit-code)"

CC: (none) => doktor5000
Hardware: i586 => All
Whiteboard: (none) => MGA3TOO

Comment 2 Colin Guthrie 2013-12-07 16:33:31 CET
(In reply to Florian Hubold from comment #1)
> Weird thing is, can't see the reason for that status "Active: failed
> (Result: exit-code)"

It says quite clearly that the exit code from the sysvinit script failed:

         Process: 1210 ExecStart=/etc/rc.d/init.d/network start (code=exited, status=1/FAILURE)

So for whatever reason it's returning failure.

On a fresh boot can you attach the "journalctl -b -u network" output?
Comment 3 Florian Hubold 2013-12-08 21:52:51 CET
(In reply to Colin Guthrie from comment #2)
> So for whatever reason it's returning failure.
> 
> On a fresh boot can you attach the "journalctl -b -u network" output?

Here it is:

[doktor5000@Mageia3 ~]$ sudo journalctl -b -a --no-pager -u network
-- Logs begin at Sat, 2013-09-28 20:17:02 CEST, end at Sun, 2013-12-08 21:34:20 CET. --
Dec 08 11:18:39 Mageia3 network[1145]: Aktivieren der Loopback-Schnittstelle:  ./ifup: interface ifcfg-lo is controlled by NetworkManager; skipping.
Dec 08 11:18:39 Mageia3 network[1145]: [  OK  ]
Dec 08 11:18:39 Mageia3 network[1145]: Configuring wireless regulatory domain  [  OK  ]
Dec 08 11:18:39 Mageia3 network[1145]: Schnittstelle »eth0« aktivieren:  Fehler: Aktivierung der Verbindung ist gescheitert: Device not managed by NetworkManager or unavailable
Dec 08 11:18:39 Mageia3 network[1145]: [FEHLER]
Dec 08 11:18:40 Mageia3 network[1145]: Schnittstelle »wlan0« aktivieren:  Error for wireless request "Set Encode" (8B2A) :
Dec 08 11:18:40 Mageia3 network[1145]: SET failed on device wlan0 ; Invalid argument.
Dec 08 11:18:40 Mageia3 network[1145]: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Dec 08 11:18:40 Mageia3 network[1145]: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Dec 08 11:18:40 Mageia3 ifplugd(wlan0)[1338]: ifplugd 0.28 initializing.
Dec 08 11:18:40 Mageia3 ifplugd(wlan0)[1338]: Using interface wlan0/00:1E:65:88:0A:F6 with driver <iwlwifi> (version: 3.8.13.4-desktop-1.mga3)
Dec 08 11:18:40 Mageia3 ifplugd(wlan0)[1338]: Using detection mode: SIOCETHTOOL
Dec 08 11:18:40 Mageia3 ifplugd(wlan0)[1338]: Initialization complete, link beat not detected.
Dec 08 11:18:40 Mageia3 network[1145]: [  OK  ]
Dec 08 11:18:43 Mageia3 ifplugd(wlan0)[1338]: Link beat detected.
Dec 08 11:18:44 Mageia3 ifplugd(wlan0)[1338]: Executing '/etc/ifplugd/ifplugd.action wlan0 up'.
Dec 08 11:18:45 Mageia3 dhclient[1771]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Dec 08 11:18:45 Mageia3 dhclient[1771]: DHCPACK from 192.168.178.1
Dec 08 11:18:45 Mageia3 dhclient[1771]: bound to 192.168.178.20 -- renewal in 382193 seconds.
Dec 08 11:18:45 Mageia3 ifplugd(wlan0)[1338]: client: Determining IP information for wlan0... done.
Dec 08 11:18:45 Mageia3 ifplugd(wlan0)[1338]: Program executed successfully.


So in my case the error comes from this, which is pretty common, but nearly always bogus:

Dec 08 11:18:39 Mageia3 network[1145]: [FEHLER]
Dec 08 11:18:40 Mageia3 network[1145]: Schnittstelle »wlan0« aktivieren:  Error for wireless request "Set Encode" (8B2A) :
Dec 08 11:18:40 Mageia3 network[1145]: SET failed on device wlan0 ; Invalid argument.
Dec 08 11:18:40 Mageia3 network[1145]: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Dec 08 11:18:40 Mageia3 network[1145]: ioctl[SIOCSIWENCODEEXT]: Invalid argument

In english that is:

Dec 08 11:18:39 Mageia3 network[1145]: [ERROR]
Dec 08 11:18:40 Mageia3 network[1145]: Activating interface »wlan0«:

Rest is the same. This is with a WPA2 network.


BTW: Actually with journalctl that's a point where localization is not that good ... :/
Comment 4 Frank Griffin 2013-12-11 14:22:36 CET
Here's one from my laptop, which has an eth0 which is almost never cabled (uses the wireless mostly):

**************************************************************
[root@jaglap ~]# journalctl -a -b -u network
-- Logs begin at Tue 2013-08-20 13:32:21 EDT, end at Wed 2013-12-11 08:14:02 EST. -
Dec 06 13:53:40 localhost.localdomain systemd[1]: Starting LSB: Bring up/down netwo
Dec 06 13:53:41 jaglap network[9915]: Bringing up loopback interface:  ./ifup: inte
Dec 06 13:53:41 jaglap network[9915]: [  OK  ]
Dec 06 13:53:41 jaglap network[9915]: Configuring wireless regulatory domain  [  OK
Dec 06 13:53:41 jaglap network[9915]: Bringing up interface eth0:  ERROR    : [/etc
Dec 06 13:53:41 jaglap network[9915]: [FAILED]
Dec 06 13:53:41 jaglap network[9915]: Bringing up interface wlp2s0:  ./ifup: interf
Dec 06 13:53:41 jaglap network[9915]: [  OK  ]
Dec 06 13:53:41 jaglap systemd[1]: network.service: control process exited, code=ex
Dec 06 13:53:41 jaglap systemd[1]: Failed to start LSB: Bring up/down networking.
Dec 06 13:53:41 jaglap systemd[1]: Unit network.service entered failed state.
**************************************************************

On my desktop, it's as described as in the initial report.

It seems that if anything at all goes wrong in network, it exits with 1 whether an interface came up successfuly or not.
Comment 5 Florian Hubold 2013-12-12 23:57:54 CET
(In reply to Frank Griffin from comment #4)
> It seems that if anything at all goes wrong in network, it exits with 1
> whether an interface came up successfuly or not.

Exactly. Maybe there should be a check added that at least tries to check if default gateway can be pinged if one is defined after getting defined interfaces up - if that check is successfull, network is OK.
Comment 6 Dick Gevers 2013-12-13 09:48:36 CET
It isn't as simple as that, IMHO. No doubt for good reason it is disabled in dracut.

There are 2 different things: the network being up (which may consist of one or more interfaces, so it could be partly up and partly not - for example laptop has wired and wireless access) and then there is native systemd compatible network.service.

My network is often up. Network service as installed never is: 2 different subjects :))
Comment 7 Colin Guthrie 2013-12-13 12:03:53 CET
(In reply to Dick Gevers from comment #6)
> It isn't as simple as that, IMHO. No doubt for good reason it is disabled in
> dracut.

What is disabled in dracut specifically?

> There are 2 different things: the network being up (which may consist of one
> or more interfaces, so it could be partly up and partly not - for example
> laptop has wired and wireless access) 

Yes, this is very deliberately split into two - "network" and "network-up" (as services and network.target and network-online.target as systemd targets). Both are separate for good reason. The services themeselves should not really be used for other services for ordering purposes - they should use the targets. But this is getting a little beyond the scope of this bug report.

Either way, the fact that network.service "fails" is currently purely cosmetic. It still does it's job AFAIUI. I'm not sure if any other services fail as a result currently as they are all ordered after/require network.target which should be unaffected (please correct me if I'm wrong).

> and then there is native systemd compatible network.service.

This will never happen. The initscripts will continue for a while and when the networking support developed for the CoreOS folks is complete, we will likely switch to that.

There is no need for a "systemd compatible" network.service. The current one is perfectly compatibile - it just needs some tweaks.

I have updated the initscripts package in git but not heard from Thomas what he wanted to do with it so never pushed it. I'd rather see if it has bugs in it before trying to edit code that I'd rather not fiddle too much with. Although if it's a simple change then I have no problem patching it in.

> My network is often up. Network service as installed never is: 2 different
> subjects :))

Yup, this is why I'm saying it's usually a cosmetic issue!
Comment 8 Dave Hodgins 2014-03-07 22:43:56 CET
I'm running into this now too on Magiea 4 x86_64. Not sure if it's actually the same bug. I have the testing repos enabled, as update repos, with all updates
installed. This is on real hardware, upgraded from Mageia 3, with one nic.

systemd-analyze blame|head -n 1
            5min network.service

systemctl -a status network.service
network.service - LSB: Bring up/down networking
   Loaded: loaded (/etc/rc.d/init.d/network)
   Active: failed (Result: timeout) since Fri 2014-03-07 16:19:13 EST; 5min ago
  Process: 4848 ExecStart=/etc/rc.d/init.d/network start (code=killed, signal=TERM)

Mar 07 16:14:13 x3.hodgins.homeip.net systemd-sysctl[4871]: Overwriting earlier assignment of kernel/sysrq in file '/usr/lib/sysctl.d/50-default.conf'.
Mar 07 16:14:13 x3.hodgins.homeip.net network[4848]: Bringing up loopback interface:  [  OK  ]
Mar 07 16:14:13 x3.hodgins.homeip.net network[4848]: Enabling IPv4 packet forwarding [  OK  ]
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: network.service operation timed out. Terminating.
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: Failed to start LSB: Bring up/down networking.
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: Unit network.service entered failed state.
Mar 07 16:19:13 x3.hodgins.homeip.net network[4848]: Bringing up interface eth0:   [  OK  ]

journalctl -a -b -u network
-- Logs begin at Mon 2013-10-07 17:34:43 EDT, end at Fri 2014-03-07 16:24:50 EST. --
Mar 07 16:14:13 x3.hodgins.homeip.net systemd[1]: Starting LSB: Bring up/down networking...
Mar 07 16:14:13 x3.hodgins.homeip.net systemd-sysctl[4871]: Overwriting earlier assignment of kernel/sysrq in file '/usr/lib/sysctl.d/50-default.conf'.
Mar 07 16:14:13 x3.hodgins.homeip.net network[4848]: Bringing up loopback interface:  [  OK  ]
Mar 07 16:14:13 x3.hodgins.homeip.net network[4848]: Enabling IPv4 packet forwarding [  OK  ]
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: network.service operation timed out. Terminating.
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: Failed to start LSB: Bring up/down networking.
Mar 07 16:19:13 x3.hodgins.homeip.net systemd[1]: Unit network.service entered failed state.
Mar 07 16:19:13 x3.hodgins.homeip.net network[4848]: Bringing up interface eth0:   [  OK  ]

CC: (none) => davidwhodgins

Comment 9 Dave Hodgins 2014-03-07 23:10:52 CET
Figured out the problem on my system. I now get
systemd-analyze blame|grep network
           325ms network.service
            34ms network-up.service

The problem was that I had NetworkManager.service disabled, since I don't use
it. 

Now that drakx-net uses 'automatic' NM mode, it needs to ensure NetworkManager
is either not installed, or is enabled.
Comment 10 Colin Guthrie 2014-03-10 19:59:40 CET
(In reply to Dave Hodgins from comment #9)
> Now that drakx-net uses 'automatic' NM mode, it needs to ensure
> NetworkManager
> is either not installed, or is enabled.

This shouldn't be the case... the NM support *should* not run in initscripts if NM is installed but not running (there is a function in initscripts called is_nm_running IIRC).

So can you try reinstalling NM to see if it's easily reproducable again simply by installing it?
Comment 11 Marja Van Waes 2017-03-21 08:38:24 CET
(In reply to Colin Guthrie from comment #10)
> (In reply to Dave Hodgins from comment #9)
> > Now that drakx-net uses 'automatic' NM mode, it needs to ensure
> > NetworkManager
> > is either not installed, or is enabled.
> 
> This shouldn't be the case... the NM support *should* not run in initscripts
> if NM is installed but not running (there is a function in initscripts
> called is_nm_running IIRC).
> 
> So can you try reinstalling NM to see if it's easily reproducable again
> simply by installing it?

@ Dave

Did you try?

(This bug is, still or again, valid in current cauldron)

CC: (none) => marja11
Whiteboard: MGA3TOO => MGA5TOO

Comment 12 Dave Hodgins 2017-03-25 06:49:24 CET
Closing as old

Status: NEW => RESOLVED
Resolution: (none) => OLD


Note You need to log in before you can comment on or make changes to this bug.