QA » openQA Project » openQA Infrastructure

Looks like it just took too long:

-- Reboot --
Mai 01 03:38:52 openqaworker5 systemd[1]: Starting os-autoinst openvswitch helper...
Mai 01 03:39:00 openqaworker5 systemd[1]: Started os-autoinst openvswitch helper.
Mai 01 03:39:01 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1200s left ...
Mai 01 03:39:02 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1199s left ...
…
Mai 01 03:59:01 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 3s left ...
Mai 01 03:59:02 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 2s left ...
Mai 01 03:59:03 openqaworker5 os-autoinst-openvswitch[1734]: can't parse bridge local port IP at /usr/lib/os-autoinst/os-autoinst-openvswitch line 66.
Mai 01 03:59:03 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1s left ...
Mai 01 03:59:03 openqaworker5 systemd[1]: os-autoinst-openvswitch.service: Main process exited, code=exited, status=255/EXCEPTION
Mai 01 03:59:03 openqaworker5 systemd[1]: os-autoinst-openvswitch.service: Failed with result 'exit-code'.
Mai 02 11:25:51 openqaworker5 systemd[1]: Starting os-autoinst openvswitch helper...
Mai 02 11:25:52 openqaworker5 systemd[1]: Started os-autoinst openvswitch helper.
Mai 02 11:25:53 openqaworker5 os-autoinst-openvswitch[3664]: Waiting for IP on bridge 'br1', 1200s left ...
Mai 02 11:25:54 openqaworker5 os-autoinst-openvswitch[3664]: Waiting for IP on bridge 'br1', 1199s left ...
…
Mai 02 11:27:38 openqaworker5 os-autoinst-openvswitch[3664]: Waiting for IP on bridge 'br1', 1095s left ...
Mai 02 11:27:39 openqaworker5 os-autoinst-openvswitch[3664]: Waiting for IP on bridge 'br1', 1094s left ...
Mai 02 12:52:23 openqaworker5 ovs-vsctl[37226]: ovs|00001|vsctl|INFO|Called as ovs-vsctl set port tap5 tag=68 vlan_mode=dot1q-tunnel
Mai 02 12:52:23 openqaworker5 ovs-vsctl[37566]: ovs|00001|vsctl|INFO|Called as ovs-vsctl set port tap2 tag=58 vlan_mode=dot1q-tunnel
Mai 02 12:52:24 openqaworker5 ovs-vsctl[38374]: ovs|00001|vsctl|INFO|Called as ovs-vsctl set port tap38 tag=18 vlan_mode=dot1q-tunnel
Mai 02 12:52:26 openqaworker5 ovs-vsctl[38635]: ovs|00001|vsctl|INFO|Called as ovs-vsctl set port tap29 tag=18 vlan_mode=dot1q-tunnel
Mai 02 12:52:26 openqaworker5 ovs-vsctl[38639]: ovs|00001|vsctl|INFO|Called as ovs-vsctl set port tap1 tag=25 vlan_mode=dot1q-tunnel

Judging by the code, the exception in the end is "normal" if the bridge's IP isn't assigned in time.

The timeout has already been increased:

# /etc/systemd/system/os-autoinst-openvswitch.service.d/30-init-timeout.conf
[Service]
Environment="OS_AUTOINST_OPENVSWITCH_INIT_TIMEOUT=1200"

(There are no further drop-in configs for the service.)

The full journal shows that the network took apparently very long to setup as other services run into network-related errors as well:

Mai 01 03:40:11 openqaworker5 worker[1850]: [warn] [pid:1850] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Mai 01 03:40:11 openqaworker5 worker[1853]: [warn] [pid:1853] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Mai 01 03:40:11 openqaworker5 worker[1832]: [warn] [pid:1832] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Mai 01 03:40:12 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1129s left ...
Mai 01 03:40:13 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1128s left ...
Mai 01 03:40:14 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1127s left ...
Mai 01 03:40:15 openqaworker5 openqa-worker-cacheservice-minion[2419]: [2419] [i] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50 GiB
Mai 01 03:40:15 openqaworker5 openqa-worker-cacheservice-minion[2419]: [2419] [i] Resetting all leftover locks after restart
Mai 01 03:40:15 openqaworker5 openqa-worker-cacheservice-minion[2419]: [2419] [i] Worker 2419 started
Mai 01 03:40:15 openqaworker5 openqa-worker-cacheservice-minion[2419]: [2419] [i] Worker 2419 stopped
Mai 01 03:40:15 openqaworker5 systemd[1]: openqa-worker-cacheservice-minion.service: Main process exited, code=exited, status=88/n/a
Mai 01 03:40:15 openqaworker5 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
Mai 01 03:40:15 openqaworker5 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Mai 01 03:40:15 openqaworker5 systemd[1]: Stopped OpenQA Worker Cache Service.
Mai 01 03:40:15 openqaworker5 systemd[1]: Started OpenQA Worker Cache Service.
Mai 01 03:40:15 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1126s left ...
Mai 01 03:40:15 openqaworker5 systemd[1]: Started OpenQA Worker Cache Service Minion.
Mai 01 03:40:15 openqaworker5 openqa-workercache-daemon[2426]: [2426] [i] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50 GiB
Mai 01 03:40:15 openqaworker5 openqa-workercache-daemon[2426]: Can't create listen socket: Address family for hostname not supported at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop.pm line 124.
Mai 01 03:40:15 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Main process exited, code=exited, status=22/n/a
Mai 01 03:40:15 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Failed with result 'exit-code'.
Mai 01 03:40:15 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Scheduled restart job, restart counter is at 15.
…
Mai 01 03:59:02 openqaworker5 worker[1867]: [warn] [pid:1867] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Mai 01 03:59:02 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 2s left ...
Mai 01 03:59:02 openqaworker5 openqa-workercache-daemon[5099]: [5099] [i] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50 GiB
Mai 01 03:59:02 openqaworker5 openqa-workercache-daemon[5099]: Can't create listen socket: Address family for hostname not supported at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop.pm line 124.
Mai 01 03:59:02 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Main process exited, code=exited, status=22/n/a
Mai 01 03:59:02 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Failed with result 'exit-code'.
Mai 01 03:59:02 openqaworker5 systemd[1]: openqa-worker-cacheservice.service: Scheduled restart job, restart counter is at 224.
Mai 01 03:59:02 openqaworker5 systemd[1]: Stopping OpenQA Worker Cache Service Minion...
Mai 01 03:59:03 openqaworker5 os-autoinst-openvswitch[1734]: can't parse bridge local port IP at /usr/lib/os-autoinst/os-autoinst-openvswitch line 66.
Mai 01 03:59:03 openqaworker5 os-autoinst-openvswitch[1734]: Waiting for IP on bridge 'br1', 1s left ...
Mai 01 03:59:03 openqaworker5 systemd[1]: os-autoinst-openvswitch.service: Main process exited, code=exited, status=255/EXCEPTION
Mai 01 03:59:03 openqaworker5 systemd[1]: os-autoinst-openvswitch.service: Failed with result 'exit-code'.
Mai 01 03:59:05 openqaworker5 telegraf[1745]: 2022-05-01T01:59:05Z E! [outputs.influxdb] when writing to [http://openqa-monitor.qa.suse.de:8086]: Post "http://openqa-monitor.qa.suse.de:8086/write?db=telegraf": dial tcp: lookup openqa-monitor.qa.suse.de on [::1]:53: read udp [::1]:41586->[::1]:53: read: connection >
Mai 01 03:59:05 openqaworker5 telegraf[1745]: 2022-05-01T01:59:05Z E! [agent] Error writing to outputs.influxdb: could not write any address
Mai 01 03:59:07 openqaworker5 openqa-worker-cacheservice-minion[5100]: [5100] [i] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50 GiB
Mai 01 03:59:07 openqaworker5 openqa-worker-cacheservice-minion[5100]: [5100] [i] Resetting all leftover locks after restart
Mai 01 03:59:07 openqaworker5 openqa-worker-cacheservice-minion[5100]: [5100] [i] Worker 5100 started
Mai 01 03:59:07 openqaworker5 openqa-worker-cacheservice-minion[5100]: [5100] [i] Worker 5100 stopped
Mai 01 03:59:07 openqaworker5 systemd[1]: openqa-worker-cacheservice-minion.service: Main process exited, code=exited, status=176/n/a
Mai 01 03:59:07 openqaworker5 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
Mai 01 03:59:07 openqaworker5 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Mai 01 03:59:07 openqaworker5 systemd[1]: Stopped OpenQA Worker Cache Service.

The network was not restored automatically so a retry within/of our service wouldn't have helped (as it didn't help for the cache service).

The network has only been restored on the next day:

Mai 02 11:27:39 openqaworker5 wickedd-dhcp4[3667]: eth0: Request to acquire DHCPv4 lease with UUID 05a46f62-2e0c-0500-690e-00009a000000
Mai 02 11:27:39 openqaworker5 kernel: NET: Registered protocol family 17
Mai 02 11:27:39 openqaworker5 wickedd-dhcp6[1423]: eth0: Request to acquire DHCPv6 lease with UUID 05a46f62-2e0c-0500-690e-00009b000000 in mode auto
Mai 02 11:27:39 openqaworker5 os-autoinst-openvswitch[3664]: Waiting for IP on bridge 'br1', 1094s left ...
Mai 02 11:27:39 openqaworker5 nscd[1333]: 1333 ignored inotify event for `/etc/resolv.conf` (file exists)
Mai 02 11:27:39 openqaworker5 nscd[1333]: 1333 ignored inotify event for `/etc/resolv.conf` (file exists)
Mai 02 11:27:39 openqaworker5 wickedd-dhcp4[3667]: eth0: Committed DHCPv4 lease with address 10.160.1.93 (lease time 64800 sec, renew in 32400 sec, rebind in 56700 sec)

I suppose that happened only because @okurz invoked systemctl start default.target.

So the failing os-autoinst-openvswitch is a mere symptom and further retried wouldn't help. It looks like wicket's startup got stuck due to a dependency issue:

martchus@openqaworker5:~> sudo journalctl --boot -u wicked
-- Logs begin at Thu 2022-04-28 03:31:31 CEST, end at Tue 2022-05-03 17:23:44 CEST. --
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found ordering cycle on wicked.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on wickedd.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on wickedd-auto4.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on dbus.service/verify-active
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on basic.target/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on sockets.target/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on xvnc.socket/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on YaST2-Firstboot.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on YaST2-Second-Stage.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on systemd-user-sessions.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on remote-fs.target/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on iscsi.service/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Found dependency on network-online.target/start
Mai 01 03:38:18 openqaworker5 systemd[1]: network-online.target: Job wicked.service/start deleted to break ordering cycle starting with network-online.target/start
Mai 02 11:25:52 openqaworker5 systemd[1]: Starting wicked managed network interfaces...
Mai 02 11:26:22 openqaworker5 wicked[3708]: lo              up
Mai 02 11:26:22 openqaworker5 wicked[3708]: eth0            device-not-running
Mai 02 11:26:22 openqaworker5 wicked[3708]: ovs-system      device-not-running

• This looks to be a dependency issue / race condition
• Can we reduce the prio to High?
  • Yes, it is not happening everywhere; not sure how to even reproduce it
• It seems related to the overarching multi-machine setup / how we manage the network
  • Not really; none of that units were part of the dependency cycle.

We're not the only ones with this kind of issue (e.g. https://bugs.launchpad.net/ubuntu/+source/nbd/+bug/1487679, https://forum.siduction.org/index.php?topic=7993.0, https://bugzilla.redhat.com/show_bug.cgi?id=1600823). There's even a SUSE-specific issue (https://www.suse.com/zh-cn/support/kb/doc/?id=000018796) but we are not in that particular situation. (We have a nfs mount but there are no nested mounts within.)

I'm still trying to figure out which of the services in "our" cycle is the culprit.

TLDR: I suspect the culprit is Before=xvnc.socket in YaST2-Firstboot.service/YaST2-Second-Stage.service. Note that this is also the only significant difference to my TW system where I reboot very often and never run into this issue.

This is the list of dependencies systemd's walked through until it detected the cycle (same order as in the journal entry):

 1. network-online.target                systemd's starting point
 2. wicked.service/start                 because `Before=network-online.target`, makes sense
 3. wickedd.service/start                because `Before=wicked.service`, makes sense
 4. wickedd-auto4.service/start          because `Before=wickedd.service wicked.service`, makes sense
 5. dbus.service/verify-active           because `systemctl list-dependencies --before dbus.service` shows `wickedd.service` (and other wicked services)
                                         but why? maybe because it requires a socket unit (`Requires=dbus.socket`) which in turn requires any of the previous points
                                         it is the same on my TW system (except that the precessor is `NetworkManager.service`)
 6. basic.target/start                   because `systemctl list-dependencies --before basic.target` shows `wickedd.service` (and other wicked services)
                                         but why? it is *not* due to the NFS mount because it is the same on my TW system (except that the precessor is `NetworkManager.service`)
 7. sockets.target/start                 because `systemctl list-dependencies --before sockets.target` shows `basic.target`
                                         but why?
 8. xvnc.socket/start                    because `systemctl list-dependencies --before xvnc.socket` shows `sockets.target`
                                         presumably due to `WantedBy=sockets.target`
 9. YaST2-Firstboot.service/start        because `Before=xvnc.socket` (8.), does it make sense?
10. YaST2-Second-Stage.service/start     because `Before=xvnc.socket` (8.), does it make sense?
11. systemd-user-sessions.service/start  because `systemctl list-dependencies --before systemd-user-sessions.service` shows `YaST2-Second-Stage.service`
                                         due to `After=systemd-user-sessions.service` in YaST2-Second-Stage.service
12. remote-fs.target/start               because `systemctl list-dependencies --before remote-fs.target` shows `systemd-user-sessions.service`
                                         due to `After=remote-fs.target` in systemd-user-sessions.service
13. iscsi.service/start                  because `Before=remote-fs.target`
14. network-online.target/start          because `After=network-online.target` in iscsi.service

• I assume the list is sorted so a unit further down the list needs to be started before a unit further up in the list.
• I guess then the most interesting question is why remote-fs.target is required by any of the units further up in the list because it is of course wrong requiring this target to be started before network-online.target (while it makes sense that remote-fs.target itself requires to be started after network-online.target).
• I've been comparing this to my TW system (which I reboot daily and sometimes more often but never experienced that problem). It looks very similar except that wicked services are replaced by NetworkManager.service. There's are other differences, though:
  • The YaST2 services (9. and 10.) do not have the ordering Before=xvnc.socket.
  • Actually there are no further differences. I assume it is really the YaST2 services which make the difference.

Considering

martchus@openqaworker5:~> systemctl list-dependencies --reverse var-lib-openqa-share.mount
var-lib-openqa-share.mount
● └─openqa-worker.target
martchus@openqaworker5:~> systemctl list-dependencies --after var-lib-openqa-share.mount
var-lib-openqa-share.mount
● ├─-.mount
● ├─openqa_nvme_prepare.service
● ├─system.slice
● ├─systemd-journald.socket
● ├─var-lib-openqa-share.automount
● ├─var-lib-openqa.mount
● ├─network-online.target
● │ ├─wicked.service
● │ └─network.target
● │   ├─openvswitch.service
● │   ├─ovs-vswitchd.service
● │   ├─ovsdb-server.service
● │   ├─wicked.service
● │   ├─wickedd-auto4.service
● │   ├─wickedd-dhcp4.service
● │   ├─wickedd-dhcp6.service
● │   ├─wickedd-nanny.service
● │   ├─wickedd.service
● │   └─network-pre.target
● │     └─firewalld.service
● ├─network.target
● │ ├─openvswitch.service
● │ ├─ovs-vswitchd.service
● │ ├─ovsdb-server.service
● │ ├─wicked.service
● │ ├─wickedd-auto4.service
● │ ├─wickedd-dhcp4.service
● │ ├─wickedd-dhcp6.service
● │ ├─wickedd-nanny.service
● │ ├─wickedd.service
● │ └─network-pre.target
● │   └─firewalld.service
● └─remote-fs-pre.target
●   ├─dracut-initqueue.service
●   ├─iscsid.service
●   └─iscsiuio.service

the NFS mount is only required by the worker and the ordering doesn't look cyclic. So I don't think the NFS mount is the culprit.

If the conclusion from my last comment is right, the problematic package is yast2-installation developed at https://github.com/yast/yast-installation. I found the PR https://github.com/yast/yast-installation/pull/1041 in that repository and it looks like our issue, indeed. (Except that another unit in the cycle is deleted in their case but I assume the concrete unit which is deleted to break the cycle is a random pick.) Note that I haven't found this issue when Googling for the error message because it only contains the error message in form of a screenshot. (If I would have found the issue that would have saved me a lot of my own investigation.)

So we need to get yast2-installation updated on our system or fix is via a drop-in config.

mkittler wrote:

So we need to get yast2-installation updated on our system or fix is via a drop-in config.

To receive the proper fix would likely mean waiting for https://build.suse.de/request/show/270972 to be accepted into SLE and then forwarded to Leap. As a workaround you could try the drop-in or actually rollback yast2-installation to an earlier, unaffected version and lock the package until we have the SLE update available.

I've just tried upgrading but still got the broken yast2-installation-4.3.50-150300.3.27.1.noarch.

Apparently we're waiting for https://smelt.suse.de/request/272018.