QA (public) » openQA Project (public)

Likely can be reproduced by configuring a worker to connect to two web UI hosts where one can not be reached at all (e.g. valid DNS entry but host not up)

I can not reproduce the problem that way. All the acceptance criteria are met - also when some of the configured web UI hosts are not reachable. Of course error messages for the failed registration attempts are logged continuously (also during the execution of a job for another web UI) but I don't consider that a problem.

Unfortunately the journal from the time the issue occurred is not present anymore. The ticket description also didn't state why the worker was broken at that time. However, the worker always adds an error message for its brokenness (e.g. cache service is down) and that would be very helpful to know. I also don't know any way the worker would declare itself broken because it can not connect to a web UI host. So I suppose the worker being broken and the failing attempts to register to another web UI were unrelated. We recently had problems with the SQLite database which could have been the cause of the broken state.

confirm working in OSD infrastructure
remove workarounds, e.g. ensure baremetal-support.qa.suse.de is added back to salt-pillars-openqa for grenache-1

At this point baremetal-support.qa.suse.de is back and grenache-1 registers correctly with it and OSD.

crosscheck and extend tests

We already have a very basic test for a configuration with multiple hosts but nothing where it will actually connect to any of the configured hosts.

Considering that it actually seems to work it looks more like the worker was broken for another reason - especially because the explicit "broken" state can so far only be reached if the cache service is unavailable, when there's a leftover QEMU process or when the pool directory is locked. There's really no code which would lead it to go into the "broken" state for anything else so far. So all I can do is extending the unit tests.

PR with tests are merged. I read #78390#note-6 . If you can't reproduce the issue easily maybe try to reproduce with the instances involved originally, e.g. coordinate with admins of baremetal-support.qa a controlled shutdown and check how the osd workers behave.

I'm wondering whether that's really worth the effort considering the broken state had very likely nothing to do with the failed connection attempts. There's simply no code which would bring connection failures and the "brokenness detection" together.

By the way, AC2 makes no sense if you read it on its own because it would mean removing the "broken" state completely. However, I assume that's not what we want.
And about AC3: So far the worker does not retry multiple minutes but actually endlessly. The only exception are authorization errors. But I guess that still counts as satisfying the AC.

Looks like the saw the problem on grenache-1 now again anyways. It showed up as broken on OSD and couldn't connect to baremetal-support.qa.suse.de at all.

The worker log looked like this:

Dez 07 11:44:56 grenache-1 worker[6746]: [error] [pid:6746] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 07 11:44:56 grenache-1 worker[6746]: [info] [pid:6746] Registering with openQA baremetal-support.qa.suse.de
Dez 07 11:44:56 grenache-1 worker[6746]: [warn] [pid:6746] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
…
Dez 07 11:51:31 grenache-1 worker[6746]: [error] [pid:6746] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 07 11:51:31 grenache-1 worker[6746]: [info] [pid:6746] Registering with openQA baremetal-support.qa.suse.de
Dez 07 11:51:31 grenache-1 worker[6746]: [warn] [pid:6746] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Dez 07 11:51:41 grenache-1 worker[6746]: [info] [pid:6746] Registering with openQA baremetal-support.qa.suse.de
Dez 07 11:51:41 grenache-1 worker[6746]: [warn] [pid:6746] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
…

and the reason for the brokenness shown on OSD was Cache service info error: Can't connect: Address family for hostname not supported.

So as previously figured the worker did not show up as broken on OSD because it couldn't connect to the 2nd web UI host but because it couldn't connect to the cache service. After restarting the worker services both connections (cache service and baremetal-support.qa.suse.de) worked again. Not sure why that was necessary and the further connection attempts (for both connections) didn't work. In both cases the Mojolicious framework (and its underlying Perl modules) are used to connect. These apparently can get stuck in an error state. For now I've just restarted all worker slots again.

The error Address family for hostname not supported comes from IO::Socket::IP. The fact that we keep getting the same error over and over probably means that it gets stuck somewhere.

By the way, it was only required to restart the workers. I haven't restarted the cache service or the web UI on baremetal-support.qa.suse.de. And cccording to its log the cache service was listening on both, IPv4 and IPv6:

Dez 06 03:35:35 grenache-1 openqa-workercache-daemon[6673]: Web application available at http://127.0.0.1:9530
Dez 06 03:35:35 grenache-1 openqa-workercache-daemon[6673]: Web application available at http://[::1]:9530

And IO::Socket::IP just calls the c'tor of its base class IO::Socket. I couldn't find anything related in its documentation. I've also checked Socket. The error itself comes from the OS anyways so maybe there's even some strange caching on system level going on?

today grenache-1 workers report as "Broken", e.g. https://openqa.suse.de/admin/workers/1207 , systemctl status shows:

# systemctl status openqa-worker@10
● openqa-worker@10.service - openQA Worker #10
   Loaded: loaded (/usr/lib/systemd/system/openqa-worker@.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/openqa-worker@.service.d
           └─30-openvswitch.conf
   Active: active (running) since Wed 2020-12-09 22:41:30 CET; 10h ago
 Main PID: 7213 (worker)
    Tasks: 1
   CGroup: /openqa.slice/openqa-worker.slice/openqa-worker@10.service
           └─7213 /usr/bin/perl /usr/share/openqa/script/worker --instance 10

Dec 10 09:06:38 grenache-1 worker[7213]: [info] [pid:7213] Registering with openQA baremetal-support.qa.suse.de
Dec 10 09:06:38 grenache-1 worker[7213]: [warn] [pid:7213] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Dec 10 09:06:48 grenache-1 worker[7213]: [info] [pid:7213] Registering with openQA baremetal-support.qa.suse.de
Dec 10 09:06:48 grenache-1 worker[7213]: [warn] [pid:7213] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Dec 10 09:06:58 grenache-1 worker[7213]: [info] [pid:7213] Registering with openQA baremetal-support.qa.suse.de
Dec 10 09:06:58 grenache-1 worker[7213]: [warn] [pid:7213] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Dec 10 09:07:08 grenache-1 worker[7213]: [info] [pid:7213] Registering with openQA baremetal-support.qa.suse.de
Dec 10 09:07:08 grenache-1 worker[7213]: [warn] [pid:7213] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Dec 10 09:07:18 grenache-1 worker[7213]: [info] [pid:7213] Registering with openQA baremetal-support.qa.suse.de
Dec 10 09:07:18 grenache-1 worker[7213]: [warn] [pid:7213] Failed to register at baremetal-support.qa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds

even though the error message might just be a symptom, we can at least try to improve that as well.

@okurz But the "broken" state of the worker on OSD is not a symptom of the failed registration attempts to the 2nd web UI. The "broken" state of the worker on OSD is caused by the worker being unable to connect to the cache service. And that, in turn is caused by the same underlying connection problem which also let's the registration attempts fail. So no, I don't think the error message can be improved here. And if you would have looked a little bit further into the log you would have also spotted lines like Dez 10 09:38:48 grenache-1 worker[7238]: [error] [pid:7238] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported. These lines are the cause for the broken state on OSD.

grenache-1 has been restarted before I could restart the worker services. However, after the restart the problem persisted. So this problem maybe happens especially after a reboot. Possibly the service is started before the network is ready. Only after restarting the worker services via systemctl restart openqa-worker@{1..40} they behave as normal again.

mkittler wrote:

grenache-1 has been restarted before I could restart the worker services. However, after the restart the problem persisted. So this problem maybe happens especially after a reboot. Possibly the service is started before the network is ready. Only after restarting the worker services via systemctl restart openqa-worker@{1..40} they behave as normal again.

kind of. After the report today that grenache-1 workers where offline again I assigned an v6 address to baremetal-support.qa.suse.de and added an according AAAA record to qanet's DNS server.
I then was fighting with the nscd service which cached the "NXDOMAIN" result for this webui. After restarting nscd the workers seem to be connected. I'm not sure if our actions crossed and your restarting of the service made them work again but I think it was just done automatically

So I also ran sudo systemctl restart openqa-worker@{1..10} on openqaworker10 and it seems to have brought those back online - but that's probably going to break after the next reboot 🤔

What was wrong with openqaworker10? Did it show the same log/broken messages?

mkittler wrote:

What was wrong with openqaworker10? Did it show the same log/broken messages?

Yeah, it was showing up as broken in the web UI and had the network errors mentioned in this ticket. I saw this after rebooting it with 15.2 wondering why it wouldn't pick up jobs.

This issue happens again in 2020-12-14 in some workers.
I tried to restart nscd firstly, but the workers' status is still broken, so I did systemctl restart openqa-worker@{1..40} in grenache-1.
I restarted the nscd at that time:

xiaojing@grenache-1:~> systemctl status nscd.service 
● nscd.service - Name Service Cache Daemon
   Loaded: loaded (/usr/lib/systemd/system/nscd.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-12-14 04:03:29 CET; 11min ago
  Process: 33430 ExecStop=/usr/sbin/nscd --shutdown (code=exited, status=0/SUCCESS)
  Process: 33432 ExecStart=/usr/sbin/nscd (code=exited, status=0/SUCCESS)

And after 2020-12-14 04:03:29, the worker log showed [error] until restarting

Dec 14 03:54:57 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 03:59:52 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:04:47 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:09:43 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:12:06 grenache-1 worker[4656]: [info] [pid:4656] Quit due to signal TERM
Dec 14 04:12:06 grenache-1 worker[4656]: [debug] [pid:4656] Informing baremetal-support.qa.suse.de that we are going offline
Dec 14 04:12:06 grenache-1 worker[4656]: [debug] [pid:4656] Informing openqa.suse.de that we are going offline
Dec 14 04:12:06 grenache-1 systemd[1]: Stopping openQA Worker #10...
Dec 14 04:13:36 grenache-1 systemd[1]: openqa-worker@10.service: State 'stop-sigterm' timed out. Killing.

The same issue happened in arm-1, arm-2, openqaworker10, run systemctl restart openqa-worker on those hosts.

Xiaojing_liu wrote:

This issue happens again in 2020-12-14 in some workers.
I tried to restart nscd firstly, but the workers' status is still broken, so I did systemctl restart openqa-worker@{1..40} in grenache-1.
I restarted the nscd at that time:

xiaojing@grenache-1:~> systemctl status nscd.service 
● nscd.service - Name Service Cache Daemon
   Loaded: loaded (/usr/lib/systemd/system/nscd.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-12-14 04:03:29 CET; 11min ago
  Process: 33430 ExecStop=/usr/sbin/nscd --shutdown (code=exited, status=0/SUCCESS)
  Process: 33432 ExecStart=/usr/sbin/nscd (code=exited, status=0/SUCCESS)

And after 2020-12-14 04:03:29, the worker log showed [error] until restarting

Dec 14 03:54:57 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 03:59:52 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:04:47 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:09:43 grenache-1 worker[4656]: [error] [pid:4656] Worker cache not available: Cache service info error: Can't connect: Address family for hostname >
Dec 14 04:12:06 grenache-1 worker[4656]: [info] [pid:4656] Quit due to signal TERM
Dec 14 04:12:06 grenache-1 worker[4656]: [debug] [pid:4656] Informing baremetal-support.qa.suse.de that we are going offline
Dec 14 04:12:06 grenache-1 worker[4656]: [debug] [pid:4656] Informing openqa.suse.de that we are going offline
Dec 14 04:12:06 grenache-1 systemd[1]: Stopping openQA Worker #10...
Dec 14 04:13:36 grenache-1 systemd[1]: openqa-worker@10.service: State 'stop-sigterm' timed out. Killing.

The same issue happened in arm-1, arm-2, openqaworker10, run systemctl restart openqa-worker on those hosts.

thanks for handling this.
Just to add some further information: I checked grenache-1 and it seems to have a completely working v4 and v6 stack. I can ping ::1 (localhost) as well as external resources (e.g. heise.de). @mkittler Would it be possible to log the output of ip a s if we observe the error in the worker? Also: maybe an explicit connect to 127.0.0.1 instead of localhost could reduce potential issues? (not saying this is the right approach but maybe it yields some interesting results)

Would it be possible to log the output of ip a s if we observe the error in the worker?

I can do that before trying to apply any workarounds. However, it will likely only show that everything is configured correctly. But maybe at the time the worker services have been started something wasn't ready and for some reason the workers are stuck within that error state - even though the network should be fine at this point.

Now openqaworker-arm-1 is affected (all active worker slots).

Unfortunately somebody else has just restarted all the worker slots before I could do any further investigation. It works again after that but I could not follow-up on @nicksinger last comment. Note that nscd has not been restarted. So somehow I doubt that this service makes much of a difference here.

Here's just the log of one of the worker instances:

Dez 17 09:19:10 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:25:45 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:32:20 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:38:55 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:45:30 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:52:06 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 09:58:41 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 10:05:16 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 10:11:51 openqaworker-arm-1 worker[2553]: [error] [pid:2553] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Dez 17 10:14:24 openqaworker-arm-1 systemd[1]: Stopping openQA Worker #1...
Dez 17 10:14:24 openqaworker-arm-1 worker[2553]: [info] [pid:2553] Quit due to signal TERM
Dez 17 10:14:24 openqaworker-arm-1 worker[2553]: [debug] [pid:2553] Informing openqa.suse.de that we are going offline
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: openqa-worker@1.service: State 'stop-sigterm' timed out. Killing.
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: openqa-worker@1.service: Killing process 2553 (worker) with signal SIGKILL.
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: openqa-worker@1.service: Main process exited, code=killed, status=9/KILL
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: Stopped openQA Worker #1.
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: openqa-worker@1.service: Unit entered failed state.
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: openqa-worker@1.service: Failed with result 'timeout'.
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: Starting openQA Worker #1...
Dez 17 10:15:54 openqaworker-arm-1 systemd[1]: Started openQA Worker #1.

Note that in this case there's no 2nd worker instances involved at all.

By the way, this does look like a general networking issue and is not necessarily IPv6 related. I assumed that the cache service client would try to use IPv6 but the code actually hard-codes an IPv4 address (has host => sub { 'http://127.0.0.1:' . service_port('cache_service') }; instead of localhost). Of course then it is weird that when it comes to connecting to multiple web UIs sometimes the connection to OSD works but not to other web UI hosts. I thought IPv4 vs. IPv6 might be responsible here.

I need to stress again that restarting ncsd was really only needed once to get the record for the kernel-webui recognized properly and flush the cached "NX AAAA record". This will not solve any issue in the future.

I don't know how feasible this is but could we switch the communication between workers and the cacheservice to be done over unix domain sockets instead of local network communication? This would be a little bit more bulletproof in case of network misconfiguration.

I suppose it would be possible. I had to check whether there's something in Mojolicious/Minion for it.

Just for the record, it happened today again on OSD workers arm-1 and arm-2. On arm-1 restarting the worker services didn't even help unless also openqa-worker-cacheservice was restarted (no problems were visible on the journal of openqa-worker-cacheservice though).

Not sure whether there were any occurrences during my vacation but currently all slots on openqaworker-arm-1 are affected, e.g.:

-- Reboot --
Jan 14 11:12:08 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 14 11:12:59 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 14 11:13:00 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 14 11:13:01 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 14 11:13:03 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 14 11:13:42 openqaworker-arm-1 systemd[1]: Starting openQA Worker #1...
Jan 14 11:13:42 openqaworker-arm-1 systemd[1]: Started openQA Worker #1.
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [info] [pid:2549] worker 1:
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - config file:           /etc/openqa/workers.ini
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - worker hostname:       openqaworker-arm-1
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - isotovideo version:    20
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - websocket API version: 1
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - web UI hosts:          openqa.suse.de
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - class:                 qemu_aarch64,qemu_aarch64_slow_worker,tap,openqaworker-arm-1
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - no cleanup:            no
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]:  - pool directory:        /var/lib/openqa/pool/1
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [error] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [info] [pid:2549] CACHE: caching is enabled, setting up /var/lib/openqa/cache/openqa.suse.de
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Project dir for host openqa.suse.de is /var/lib/openqa/share
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:13:52 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:02 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:02 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:12 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:12 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:22 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:22 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:32 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:32 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:42 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:42 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:14:52 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:14:52 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:15:02 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:15:02 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 14 11:15:12 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registering with openQA openqa.suse.de
Jan 14 11:15:12 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Establishing ws connection via ws://openqa.suse.de/api/v1/ws/476
Jan 14 11:15:13 openqaworker-arm-1 worker[2549]: [info] [pid:2549] Registered and connected via websockets with openQA host openqa.suse.de and worker ID 476
Jan 14 11:15:13 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s
Jan 14 11:16:53 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s
Jan 14 11:20:13 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s
Jan 14 11:21:53 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s
Jan 14 11:23:33 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s
Jan 14 11:25:13 openqaworker-arm-1 worker[2549]: [warn] [pid:2549] Worker cache not available: Cache service info error: Can't connect: Address family for hostname not supported - checking again for web UI 'openqa.suse.de' in 100.00 s

Besides the actual problem, we have apparently a broken systemd override on that system.

The log clearly shows that when the worker service started the network wasn't up and both - the local connection to the cache service failed (with "Address family for hostname not supported") and the connection to openqa.suse.de (DNS resolution failed). The remote connection starts to work on its own again after serveral retries as expected. Only the local connection stays broken despite several retry attempts. At least we can observe that https://github.com/os-autoinst/openQA/pull/3646 works.

And of course the cache service itself is accessible via IPv4 and IPv6 (the worker uses IPv4):

> curl "http://[::1]:9530/foo"
Not found
> curl "http://127.0.0.1:9530/foo"
Not found

I straced the worker process (there is only one process per slot; no forking happens in that state). During the "Cache service info error" nothing is happening. On a connection attempt, the following is logged:

> sudo strace -p 2549
…
getpid()                                = 2549
ppoll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}], 1, {tv_sec=500, tv_nsec=178000000}, NULL, 0) = 1 ([{fd=3, revents=POLLOUT}], left {tv_sec=500, tv_nsec=177996730})
write(3, "\201\376\0\244\0{7\212{YE\357a\10X\344\"A\25\335o\t\\\357r[T\353c\23R\252"..., 172) = 172
getpid()                                = 2549
flock(1, LOCK_EX)                       = 0
write(1, "[warn] [pid:2549] Worker cache n"..., 186) = 186
flock(1, LOCK_UN)                       = 0
ppoll([{fd=3, events=POLLIN|POLLPRI}], 1, {tv_sec=100, tv_nsec=0}, NULL, 0) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=99, tv_nsec=742701000})
read(3, "\201 {\"population\":335,\"type\":\"info"..., 131072) = 34
ppoll([{fd=3, events=POLLIN|POLLPRI}], 1, {tv_sec=99, tv_nsec=743000000}, NULL, 0

Only the 2nd and 3rd line are interesting and it repeads endlessly like that.

The descriptor 3 is apparently some socket:

sudo ls -l /proc/2549/fd
insgesamt 0
lr-x------ 1 _openqa-worker nogroup 64 14. Jan 11:13 0 -> /dev/null
lrwx------ 1 _openqa-worker nogroup 64 14. Jan 11:13 1 -> 'socket:[67656]'
lrwx------ 1 _openqa-worker nogroup 64 14. Jan 11:13 2 -> 'socket:[67656]'
lrwx------ 1 _openqa-worker nogroup 64 14. Jan 11:13 3 -> 'socket:[85384]'

But sudo lsof -i -a -p 2549 just hanngs and show nothing and it seems not possible to get further info:

> sudo head /proc/2549/fd/3
head: '/proc/2549/fd/3' kann nicht zum Lesen geöffnet werden: Kein passendes Gerät bzw. keine passende Adresse gefunden

I get the same result for the other FDs and also for the other worker slots.

By the way, the code which checks for the cache service is $cache_service_client->info->availability_error where $cache_service_client is always the same OpenQA::CacheService::Client instance which uses always the same Mojo::UserAgent instance under the hood ($tx = $ua->$method(@args)).

I've just restarted one worker slot and as usual that helps. In the good case the trace for requests to the cache service looks like this:

socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
ioctl(3, TCGETS, 0xffffe593f420)        = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(3, 0, SEEK_CUR)                   = -1 ESPIPE (Nicht erlaubter Seek)
ioctl(3, TCGETS, 0xffffe593f420)        = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(3, 0, SEEK_CUR)                   = -1 ESPIPE (Nicht erlaubter Seek)
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(3, {sa_family=AF_INET, sin_port=htons(9530), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
fcntl(3, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)
ppoll([{fd=3, events=POLLOUT}], 1, {tv_sec=299, tv_nsec=999000000}, NULL, 0) = 1 ([{fd=3, revents=POLLOUT}], left {tv_sec=299, tv_nsec=998996819})
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [256->4]) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(9530), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(9530), sin_addr=inet_addr("127.0.0.1")}, [256->16]) = 0
setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(57106), sin_addr=inet_addr("127.0.0.1")}, [256->16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(57106), sin_addr=inet_addr("127.0.0.1")}, [256->16]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(9530), sin_addr=inet_addr("127.0.0.1")}, [256->16]) = 0
ppoll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}], 1, {tv_sec=10, tv_nsec=0}, NULL, 0) = 1 ([{fd=3, revents=POLLOUT}], left {tv_sec=9, tv_nsec=999996890})
write(3, "GET /info HTTP/1.1\r\nAccept-Encod"..., 118) = 118
ppoll([{fd=3, events=POLLIN|POLLPRI}], 1, {tv_sec=10, tv_nsec=0}, NULL, 0) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=9, tv_nsec=996292269})
read(3, "HTTP/1.1 200 OK\r\nContent-Length:"..., 131072) = 326

I'm wondering why the stuck workers don't even show a connect(3, {sa_family=AF_INET, sin_port=htons(9530), sin_addr=inet_addr("127.0.0.1")}, 16) like here. Maybe Perl or more likely getaddrinfo() remembers the last "Address family for hostname not supported" error and therefore it doesn't even try. (getaddrinfo() is not a syscall and therefore doesn't show up in strace.)

Likely we can not do anything about it except depending on network-online.target within the systemd service (to pull in wicked.service in our case). The worker currently only depends on network.target (which only pulls in openvswitch.service).

If the problem is really getaddrinfo() being stuck in that error state there's likely nothing we can do to improve except trying to make sure we don't run into the error in the first place. Hence I created a PR to make the worker depend on network-online.target: https://github.com/os-autoinst/openQA/pull/3673

We would not be the only ones running into that problem:

1. https://ask.puppet.com/question/11481/name-or-service-not-known-until-puppet-restart
2. https://unix.stackexchange.com/questions/89699/process-calling-getaddrinfo-at-boot-gets-permanently-stuck-with-bad-etc-resol
   • Apparently it helped to call res_init() which I can give a try as well.
   • It is suggested to use a local DNS resolver. We indeed don't do that already. However, I don't think it would help with the 127.0.0.1/"Address family for hostname not supported" case.
3. https://github.com/nning/transmission-rss/issues/42
   • The resolution was to rely on network-online.target.

At least for the issue with the local connection (and that seems to be the only connection which still shows this issue) we could also avoid calling getaddrinfo() at all. This would require some changes in Perl libraries we're using. Some notes from @kraih about this:

fwiw. if you wanted to optimize getaddrinfo away in some cases, i believe this is the place you would have to do it https://metacpan.org/source/PEVANS/IO-Socket-IP-0.41/lib/IO/Socket/IP.pm#L516
there is a possibility to optimize it on the mojo layer too, since IO::Socket::IP accepts a config option (PeerAddrInfo) with an already prepared getaddrinfo data structure
we use that to integrate Net::DNS::Native (async resolver) https://github.com/mojolicious/mojo/blob/296c11e4b2ee82b7609a7a0ec8d7696617bb9e69/lib/Mojo/IOLoop/Client.pm#L52
The fake version for platforms without getaddrinfo might be helpful too https://metacpan.org/release/Socket/source/Socket.pm#L970
guess for the simple 127.0.0.1 case you could just get away with pack_sockaddr_in
guess i could add an upstream feature to mojo to allow socket options to be passed with the transaction
$tx->socket_options({PeerAddrInfo => $already_prepared_data_structure});
that's quite a bit of work though (for upstream testing and docs), so we should be fairly certain we really really want this before i invest the time

The workers on openqaworker5 were broken this morning because of Address family for hostname not supported, I just restart all the worker services.

PR for a workaround from our side: https://github.com/os-autoinst/openQA/pull/3676

I rebooted openqaworker6 and openqaworker10 today after a user report in https://chat.suse.de/channel/testing?msg=udQguXCPNRcAABnBg

We can await the next osd deployment, then check for "broken" workers on https://openqa.suse.de/admin/workers

I've checked openqaworker-arm-1 and 2 and found no occurrences so far (for i in {1..10}; do sudo journalctl --no-pager --since '24 hours ago' -u openqa-worker@$i | grep -i 'Address family for hostname'; done).

I haven't seen any broken workers anymore. Note that my greping on the journal was likely not very useful because the remaining errors might have a different message. The message Name or service not known is still being logged but the worker is not stuck in that error state so that should not be a problem. The new debug message Running patched getaddrinfo() for 127.0.0.1 introduced by my workaround is also visible in the log. It clutters the log a little bit so we might consider removing that message. That's how it looks like:

[…]
Jan 24 03:39:32 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:32 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:39:42 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:42 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:39:52 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:52 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:40:02 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:40:02 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:40:12 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:40:12 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Establishing ws connection via ws://openqa.suse.de/api/v1/ws/482
Jan 24 03:40:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:40:13 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registered and connected via websockets with openQA host openqa.suse.de and worker ID 482
Jan 24 03:41:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:43:01 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 24 03:43:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:45:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:46:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:48:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:50:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:51:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:53:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:55:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:56:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:58:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:00:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:01:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:03:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:05:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:06:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:08:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:10:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:11:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:13:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:15:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:16:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:18:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:20:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:21:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:23:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:25:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:26:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:28:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:30:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:31:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:33:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:35:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:36:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:38:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:40:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:41:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:43:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:45:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:46:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:48:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:50:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:51:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:53:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:55:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:56:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 04:58:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:00:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:01:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:03:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:05:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:06:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:08:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:10:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:11:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:13:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:15:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:16:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:18:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:20:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:21:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:23:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:25:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:26:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:28:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:30:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:31:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:33:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:35:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:36:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:38:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:40:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:41:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:43:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:45:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:46:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:48:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:50:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:51:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:53:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:55:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:56:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 05:58:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:00:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:01:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:03:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:05:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:06:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:08:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:10:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:12:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:13:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:15:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:17:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:18:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:20:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:22:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:23:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:25:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:27:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:28:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:30:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:32:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:33:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:35:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:37:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:38:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:40:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:42:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:43:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:45:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:47:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:48:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:50:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:52:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:53:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:55:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:57:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 06:58:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:00:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:02:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:03:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:05:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:07:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:08:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:10:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:12:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:13:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:15:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:17:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:18:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:20:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:22:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:23:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:25:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:27:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:28:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:30:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:32:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:33:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:35:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:37:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:38:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:40:25 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:42:05 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:43:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:45:25 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:47:05 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:48:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:50:25 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:52:05 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:53:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:55:25 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:57:05 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 07:58:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:00:25 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:02:05 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:03:45 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:05:26 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:07:06 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:08:46 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:10:26 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:12:06 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:13:46 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:15:26 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:17:06 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:18:46 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:20:26 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:22:06 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:23:47 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:25:27 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:27:07 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:28:47 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:30:27 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:32:07 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:33:47 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:35:27 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:37:07 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:38:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:40:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:42:08 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:43:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:45:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:47:08 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:48:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:50:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:52:08 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:53:49 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:55:29 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:57:09 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 08:58:49 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:00:29 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:02:09 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:03:49 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:05:29 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:07:09 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:08:49 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:10:30 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:12:10 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:13:50 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:15:30 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:17:10 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:18:50 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:20:30 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:22:10 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:23:50 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:25:31 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:27:11 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:28:51 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:30:31 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:32:11 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:33:51 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:35:31 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:37:11 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:38:51 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:40:31 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:42:12 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:43:52 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:45:32 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:47:12 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:48:52 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:50:32 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:52:12 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:53:52 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:55:32 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:57:12 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 09:58:52 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:00:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:02:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:03:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:05:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:07:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:08:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:10:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:12:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:13:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:15:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:17:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:18:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:20:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:22:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:23:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:25:34 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:27:14 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:28:54 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:30:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:32:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:33:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:35:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:37:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:38:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:40:35 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:42:15 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:43:55 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:45:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:47:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:48:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:50:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:52:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:53:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:55:36 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:57:16 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 10:58:56 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:00:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:02:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:03:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:05:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:07:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:08:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:10:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:12:17 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:13:57 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:15:37 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:17:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:18:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:20:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:22:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:23:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:25:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:27:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:28:58 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:30:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:32:18 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:33:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:35:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:37:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:38:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:40:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:42:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:43:59 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:45:39 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:47:19 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:49:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:50:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:52:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:54:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:55:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:57:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 11:59:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:00:40 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:02:20 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:04:00 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:05:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:07:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:09:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:10:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:12:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:14:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:15:41 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:17:21 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:19:01 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:20:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:22:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:24:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:25:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:27:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:29:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:30:42 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:32:22 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:34:02 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:35:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:37:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:39:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:40:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:42:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:44:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:45:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:47:23 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:49:03 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:50:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:52:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:54:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:55:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:57:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 12:59:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:00:44 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:02:24 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:04 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Accepting job 5334244 from openqa.suse.de.
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Setting job 5334244 from openqa.suse.de up
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Preparing Mojo::IOLoop::ReadWriteProcess::Session
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [info] [pid:2132] +++ setup notes +++
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Running on openqaworker-arm-1:7 (Linux 5.8.3-1.gbad027a-default #1 SMP Sat Aug 22 06:31:07 UTC 2020 (bad027a) aarch64)
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Job settings:
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132]
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     AGGREGATE_NEEDED=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     ARCH=aarch64
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     BACKEND=qemu
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     BOOT_HDD_IMAGE=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     BUILD=:17943:sudo
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     BUILD_SDK=GM
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     CACHEDIRECTORY=/var/lib/openqa/cache
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     COLLECT_COREDUMPS=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     DESKTOP=textmode
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     DISTRI=sle
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     FLAVOR=Server-DVD-Incidents-Install
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     HDDMODEL=virtio-blk-device
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     HDD_1=SLES-12-SP5-aarch64-Installtest.qcow2
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     INCIDENT_ID=17943
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     INCIDENT_REPO=http://download.suse.de/ibs/SUSE:/Maintenance:/17943/SUSE_Updates_SLE-SDK_12-SP5_aarch64/,http://download.suse.de/ibs/SUSE:/Maintenance:/17943/SUSE_Updates_SLE-SERVER_12-SP5_aarch64/
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     INSTALLTEST=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     ISO=SLE-12-SP5-Server-DVD-aarch64-GM-DVD1.iso
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     JOBTOKEN=AzV8fhvPrcjGhUfN
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     LOG_LEVEL=debug
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     MACHINE=aarch64-virtio
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     MAX_JOB_TIME=9000
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     NAME=05334244-sle-12-SP5-Server-DVD-Incidents-Install-aarch64-Build:17943:sudo-qam-incidentinstall@aarch64-virtio
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     NOVIDEO=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     OPENQA_HOSTNAME=openqa.suse.de
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     OPENQA_URL=openqa.suse.de
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     OS_TEST_ISSUES=17943
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     PRJDIR=/var/lib/openqa/share
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMU=aarch64
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMUCPU=host
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMUCPUS=2
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMUMACHINE=virt,usb=off,gic-version=3,its=off
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMUPORT=20072
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     QEMU_DISABLE_SNAPSHOTS=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     REPO_ID=1611490232
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     RETRY_DELAY=5
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     RETRY_DELAY_IF_WEBUI_BUSY=60
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     SDK_TEST_ISSUES=17943
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     SERIALDEV=ttyAMA0
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     SHUTDOWN_NEEDS_AUTH=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     TEST=qam-incidentinstall
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     TEST_SUITE_NAME=qam-incidentinstall
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     UEFI=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     UEFI_PFLASH_CODE=/usr/share/qemu/aavmf-aarch64-code.bin
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     UEFI_PFLASH_VARS=SLES-12-SP5-aarch64-Installtest-uefi-vars.qcow2
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     VERSION=12-SP5
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     VGA=std
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     VIRTIO_CONSOLE=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     VNC=97
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     VNC_TYPING_LIMIT=10
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     WORKER_CLASS=qemu_aarch64,qemu_aarch64_slow_worker,tap,openqaworker-arm-1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     WORKER_HOSTNAME=10.160.0.245
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     WORKER_ID=482
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     WORKER_INSTANCE=7
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]:     ZYPPER_ORPHANED_CHECK_ONLY=1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Found HDD_1, caching SLES-12-SP5-aarch64-Installtest.qcow2
Jan 24 13:04:28 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Downloading SLES-12-SP5-aarch64-Installtest.qcow2, request #13 sent to Cache Service
Jan 24 13:04:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Updating status so job 5334244 is not considered dead.
Jan 24 13:04:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] REST-API call: POST http://openqa.suse.de/api/v1/jobs/5334244/status
Jan 24 13:04:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Updating status so job 5334244 is not considered dead.
Jan 24 13:04:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] REST-API call: POST http://openqa.suse.de/api/v1/jobs/5334244/status
Jan 24 13:04:38 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Updating status so job 5334244 is not considered dead.
Jan 24 13:04:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] REST-API call: POST http://openqa.suse.de/api/v1/jobs/5334244/status
Jan 24 13:04:43 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Updating status so job 5334244 is not considered dead.
Jan 24 13:04:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] REST-API call: POST http://openqa.suse.de/api/v1/jobs/5334244/status
Jan 24 13:04:48 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Updating status so job 5334244 is not considered dead.
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] REST-API call: POST http://openqa.suse.de/api/v1/jobs/5334244/status
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Download of SLES-12-SP5-aarch64-Installtest.qcow2 processed:
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [info] [#13] Cache size of "/var/lib/openqa/cache" is 12GiB, with limit 50GiB
[…]

mkittler wrote:

[…]
Jan 24 03:39:32 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:32 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:39:42 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:42 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:39:52 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:39:52 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:40:02 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:40:02 openqaworker-arm-1 worker[2132]: [warn] [pid:2132] Failed to register at openqa.suse.de - connection error: Can't connect: Name or service not known - trying again in 10 seconds
Jan 24 03:40:12 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registering with openQA openqa.suse.de
Jan 24 03:40:12 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Establishing ws connection via ws://openqa.suse.de/api/v1/ws/482
Jan 24 03:40:13 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:40:13 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Registered and connected via websockets with openQA host openqa.suse.de and worker ID 482
Jan 24 03:41:53 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
Jan 24 03:43:01 openqaworker-arm-1 systemd[1]: /etc/systemd/system/openqa-worker@.service.d/30-openvswitch.conf:2: Unknown lvalue 'Environment' in section 'Unit'
Jan 24 03:43:33 openqaworker-arm-1 worker[2132]: [debug] [pid:2132] Running patched getaddrinfo() for 127.0.0.1
[…]
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [info] [pid:2132] Download of SLES-12-SP5-aarch64-Installtest.qcow2 processed:
Jan 24 13:04:53 openqaworker-arm-1 worker[2132]: [info] [#13] Cache size of "/var/lib/openqa/cache" is 12GiB, with limit 50GiB
[…]

Yeah, looks pretty good. You can see how's waiting on the connection. If this isn't debug logging, it probably should be, though.

Btw what's this Unknown lvalue 'Environment' in section 'Unit'? I guess that's unrelated, but since it is related to network setup I figured I'll ask anyway. I can't find a ticket about it.

Btw what's…

I've already created a SR for this and cleaned up the file at its old location. So it is taken care of.

PR for not relying on the monkey patch anymore with Mojolicious 8.72: https://github.com/os-autoinst/openQA/pull/3704

I would mark this ticket as resolved as soon as the PR has been merged. Of course the monkey patch is still present but we can remove it easily as soon as we no longer support Mojolicious 8.72.

mkittler wrote:

PR for not relying on the monkey patch anymore with Mojolicious 8.72: https://github.com/os-autoinst/openQA/pull/3704

I would mark this ticket as resolved as soon as the PR has been merged. Of course the monkey patch is still present but we can remove it easily as soon as we no longer support Mojolicious 8.72.

Sounds sensible to me 👍

https://github.com/os-autoinst/openQA/pull/3704 is merged. If we are lucky this will be automatically deployed to osd tomorrow morning. So I suggest you give the infrastructure a quick check before resolving.

I haven't seen any broken workers so far. I've also been checking the journal of our three OSD arm workers (where the problem occurred especially frequently) and couldn't find anything. The line "Running patched…" is no longer logged after the deployment yesterday which makes sense as the workers are already at Mojolicious 8.72. So my last PR could take effect and the previously added monkey patch is no longer used.