restart wicked.service took long time

SUSE Linux Enterprise Server SLES Networking
1

On SLES 15 SP1, I tried to restart network.service by running command ‘systemctl restart network.service’, but this command took more than 30 seconds to return 0, why it took so much time?
After enabled wicked.service debug log, see time from 10:15:08 to 10:15:32, why it took 24 seconds here?

Here is log segment:
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: eth0: configuration applied to nanny
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: Calling /org/opensuse/Network/Nanny.recheck()
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: ni_dbus_object_call_variant(/org/opensuse/Network/Nanny, if=org.opensuse.Network.Nanny, method=recheck)
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=device-exists
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=device-exists
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=device-ready
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=device-ready
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=device-setup
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=device-setup
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=protocols-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=protocols-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=firewall-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=firewall-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=device-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=link-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=link-authenticated
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=lldp-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=device-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=link-up
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=link-authenticated
Jul 24 10:15:02 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/3; target_state=network-up, state_name=lldp-up
Jul 24 10:15:08 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=addrconf-up
Jul 24 10:15:08 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=network-up
Jul 24 10:15:08 goscIcChildVM-1595585511 wicked[3280]: received signal progressInfo; object_path=/org/opensuse/Network/Nanny/Interface/1; target_state=network-up, state_name=network-up
Jul 24 10:15:32 goscIcChildVM-1595585511 wicked[3280]: Interface wait time reached

2

Hi and welcome to the Forum :slight_smile:
That is just the default configuration, you can edit /etc/default/network/config and edit the WAIT_FOR_INTERFACES= timeout, even though it says empty for no wait, I’ve found 1 in there works best.

3

Thanks. I edit the /etc/sysconfig/network/config and set the WAIT_FOR_INTERFACES=1(it was 30 by default), then ‘systemctl restart network.service’ takes 10 seconds only.
I read the comment of WAIT_FOR_INTERFACES: “Some interfaces need some time to come up or come asynchronously via hotplug. WAIT_FOR_INTERFACES is a global wait for all mandatory interfaces in seconds. If empty no wait occurs.”

Any possible reason that the interfaces take more time to come up on SLES15 SP1, I tried the same steps on SLES12 SP4 (WAIT_FOR_INTERFACES=30), not seeing restart network.service takes long time.

4

Hi
I would suggest looking at the output from systemd-analyze related to wicked services. Are you using ipv4 only? If so then look at disabling/masking the ipv6 services.

5

Thanks, please find the systemd-analyze blame output
systemd-analyze blame | grep wicked.service
30.209s wicked.service

One more finding by comparing SLES15 SP1 and SLES12 SP4 wicked.service log, /org/opensuse/Network/Nanny.recheck() is called only on SLES15 SP1 when executing ‘systemctl restart network.service’.
The timeout happened at lldp-up → network-up for eth0, was it waiting for DHCP IP address? So I set eth0 to a static IP address, then timeout did NOT happen, eth0 got network-up state within 30 seconds.

6

Hi
Look at the full output rather than grepping. Also look at/for units;

systemctl list-unit-files |grep wick
7

Hi,
Here is the output:

systemctl list-unit-files | grep wick
wicked.service enabled
wickedd-auto4.service enabled
wickedd-dhcp4.service enabled
wickedd-dhcp6.service enabled
wickedd-nanny.service enabled
wickedd-pppd@.service static
wickedd.service indirect

And attach systemd-analyze blame command output in blame.log file

8

Hi
I use a static ip addresses here, so mine are;

systemctl list-unit-files | grep wick
wicked.service                                                            enabled         disabled     
wickedd-auto4.service                                                     masked          disabled     
wickedd-dhcp4.service                                                     masked          disabled     
wickedd-dhcp6.service                                                     masked          disabled     
wickedd-nanny.service                                                     enabled         disabled     
wickedd-pppd@.service                                                     static          disabled     
wickedd.service                                                           indirect        disabled

I also disable plymouth via plymouth.enable=0 or remove all the plymouth related rpms, lock and rebuilt initrd…

9

Hi
What’s the meaning of state ‘lldp-up’ for eth0? why did it take time to be next state ‘addrconf-up’ when set eth0 to DHCP ip?

10

Hi
AFAIK it’s Link Layer Discovery Protocol.

11

Thanks.
As this looks like designed behavior for SLES15, I’m thinking to increase the timeout of our code to fit the 30s+ time of systemctl restart network.service.