fedora-infrastructure

#5814 COPR builders spawning errors
Closed: Fixed Opened by clime.

Closed: Fixed
Reopen Issue

Hello, on copr-backend, we are currently getting lots of communication errors on copr builder spawning and consequent health-check process.

The errors, which are very hard to debug (I am sorry for the formatting, was taken from /var/log/copr-backend/spawner.log directly), are attached.

spawn_errors.txt

I would like to ask to confirm that communication with OpenStack works correctly.

There are also similar error logs when backen is trying to connect to frontend for new builds and actions:
(from /var/log/copr-backend/action_dispatcher.log)

action_dispatcher_cut.log

The action dispatcher error is a DNS error.
The other one is HTTP 408 Request Timeout, which would imply that you're not sending the request in a reasonable time period.

I have not seen this sorts of errors at other instances in our Infra Cloud recently, and your instance has a lot of other errors like:

[Feb19 01:51] systemd-coredump[12016]: Core Dumping has been disabled for process 4747 (systemd-journal).
[  +3.226985] systemd-journald[12018]: File /var/log/journal/a5bd9bcdf8ac4025a1973027254b5d6e/system.journal corrupted
[Feb19 02:14] systemd-coredump[17406]: Core Dumping has been disabled for process 12018 (systemd-journal).
[ +15.693549] systemd-journald[17408]: File /var/log/journal/a5bd9bcdf8ac4025a1973027254b5d6e/system.journal corrupted

And low memory errors and lots of segfaults.
Because your logs are lacking a lot of information, I am unable to see any more information around the particular times.

Could you please try to get your kernel log legible?

Not sure where did you find that log message about corrupted system.journal. Anyway, I ran 

journalctl --vacuum-size=2G

because /var/log/journal was already on the limit of 4G and afterwards also:

journalctl --verify

which passed on all the files.

The coredumps you are mentioning are coredumps in libappstream-glib* (https://bugzilla.redhat.com/show_bug.cgi?id=1426166) and yes, we definitely need to get rid of them.

The low memory errors and the subsequent OOM killer invocation happens when rdiff-backup is run on the backend server remotely by probably a periodically running playbook.

There errors, while they need to be fixed do not really explain the DNS errors when trying to get data from copr.fedorainfracloud.org. It seems there might be random dropouts in the dns servicing.

The errors with builder communication I will need to investigate further. They might be unrelated except this one:

{\n    "msg": "vm_name=Copr_builder_780832430"\n}\n\nTASK [spin/ensure vm with nova_compute] ****************************************\nfatal: [localhost -> localhost]: FAILED! => {"changed": false, "failed": true, "msg": "Error in getting the server list: HTTPSConnectionPool(host=\'fedorainfracloud.org\', port=8774): Max retries exceeded with url: /v2/5d99f099b7fe4b0387f0352f6301ba6a/servers/detail?name=Copr_builder_780832430 (Caused by NewConnectionError(\'<requests.packages.urllib3.connection.VerifiedHTTPSConnection object at 0x7f480081bd50>: Failed to establish a new connection: [Errno 110] Connection timed out\',))"}\n\nPLAY RECAP *********************************************************************\nlocalhost                  : ok=2    changed=0    unreachable=0    failed=1   \n\n', 'returncode': 2}

which again seems to point to some issue with DNS resolution for fedorainfracloud.org.

Here is an example error when builder spawning playbook was run manually from commandline:

[copr@copr-be ~][PROD]$ ansible-playbook -c ssh /home/copr/provision/builderpb_nova.yml
[DEPRECATION WARNING]: Instead of sudo/sudo_user, use become/become_user and make sure become_method is 'sudo' (default).
This feature will be removed in a future release. Deprecation warnings can be disabled by setting
deprecation_warnings=False in ansible.cfg.
PLAY [check/create instance] ***************************************************
TASK [generate builder name] ***************************************************
ok: [localhost -> localhost]
TASK [debug] *******************************************************************
ok: [localhost] => {
    "msg": "vm_name=Copr_builder_391418212"
}
TASK [spin/ensure vm with nova_compute] ****************************************
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: SSLError: EOF occurred in violation of protocol (_ssl.c:661)
fatal: [localhost]: FAILED! => {"failed": true, "msg": "Unexpected failure during module execution.", "stdout": ""}

Also put here: https://paste.fedoraproject.org/paste/eX1Fuq5k8AkFJBrfVXy~VV5M1UNdIGYhyRLivL9gydE=

Additional info to the above: The command was run at around 1:47pm UTC and the step TASK [spin/ensure vm with nova_compute] took a long time and then gave the mentioned message in the stdout.
Edited by clime

I tried to ping fedorainfracloud.org on persistent network from copr-be-dev that was spawned yesterday and it shows there are some lost packets.

[root@copr-be-dev ~][STG]# ping -I eth0 209.132.184.9
PING 209.132.184.9 (209.132.184.9) from 172.25.32.160 eth0: 56(84) bytes of data.
64 bytes from 209.132.184.9: icmp_seq=1 ttl=63 time=0.450 ms
64 bytes from 209.132.184.9: icmp_seq=2 ttl=63 time=0.468 ms
64 bytes from 209.132.184.9: icmp_seq=3 ttl=63 time=0.412 ms
64 bytes from 209.132.184.9: icmp_seq=4 ttl=63 time=0.430 ms
64 bytes from 209.132.184.9: icmp_seq=5 ttl=63 time=0.527 ms
64 bytes from 209.132.184.9: icmp_seq=6 ttl=63 time=0.646 ms
64 bytes from 209.132.184.9: icmp_seq=7 ttl=63 time=0.519 ms
64 bytes from 209.132.184.9: icmp_seq=8 ttl=63 time=0.445 ms
64 bytes from 209.132.184.9: icmp_seq=9 ttl=63 time=0.680 ms
64 bytes from 209.132.184.9: icmp_seq=12 ttl=63 time=31.9 ms
64 bytes from 209.132.184.9: icmp_seq=15 ttl=63 time=33.6 ms
64 bytes from 209.132.184.9: icmp_seq=16 ttl=63 time=30.9 ms
64 bytes from 209.132.184.9: icmp_seq=17 ttl=63 time=30.8 ms
64 bytes from 209.132.184.9: icmp_seq=18 ttl=63 time=34.9 ms
64 bytes from 209.132.184.9: icmp_seq=25 ttl=63 time=8.35 ms
64 bytes from 209.132.184.9: icmp_seq=26 ttl=63 time=38.7 ms
64 bytes from 209.132.184.9: icmp_seq=30 ttl=63 time=30.5 ms
64 bytes from 209.132.184.9: icmp_seq=32 ttl=63 time=0.368 ms
64 bytes from 209.132.184.9: icmp_seq=33 ttl=63 time=0.423 ms
64 bytes from 209.132.184.9: icmp_seq=34 ttl=63 time=0.422 ms
64 bytes from 209.132.184.9: icmp_seq=35 ttl=63 time=0.455 ms
64 bytes from 209.132.184.9: icmp_seq=36 ttl=63 time=0.313 ms
64 bytes from 209.132.184.9: icmp_seq=38 ttl=63 time=0.380 ms
64 bytes from 209.132.184.9: icmp_seq=39 ttl=63 time=0.441 ms
64 bytes from 209.132.184.9: icmp_seq=40 ttl=63 time=0.481 ms
64 bytes from 209.132.184.9: icmp_seq=41 ttl=63 time=0.377 ms
^C
--- 209.132.184.9 ping statistics ---
41 packets transmitted, 26 received, 36% packet loss, time 40862ms
rtt min/avg/max/mdev = 0.313/9.547/38.732/14.441 ms

I would really appreciate if this was looked at carefully.

There is definitely some network issue. People are reporting inaccessible fedora repo from Copr builders. E.g.:
https://copr-be.cloud.fedoraproject.org/results/mcyprian/sp-builds/fedora-26-x86_64/00520366-python3/root.log

We tracked this down to an instance that was saturating the network.

This instance has been sacked.

:purple_heart:

Metadata Update from @kevin:
- Issue close_status updated to: Fixed
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.