Task is failing with timeout message and no runner.log

[wladich]

test_commands has failed without a log in those PRs:

• [testing_master_latest] Nightly PR freeipa-pr-ci2/freeipa#881
• [testing_master_latest_selinux] Nightly PR freeipa-pr-ci2/freeipa#865
• [testing_master_rawhide] Nightly PR freeipa-pr-ci2/freeipa#824

Same suite timed out with logs:

• http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/f0edce64-abd7-11eb-a0cf-5254009a3bd6/runner.log.gz
• [testing_master_latest] Nightly PR freeipa-pr-ci2/freeipa#854, runner.log

Marked as timed out in PR but no signs of timeout in runner.log:

• [testing_master_testing_selinux] Nightly PR freeipa-pr-ci2/freeipa#817, runner.log

[wladich]

The problem with test suite timeout will be fixed in freeipa/freeipa#5748.

Here are the logs related to missing artifacts:

May 03 23:33:26 permanent-small-runner-2 bash[1675771]: INFO: __main__: Attempting to lock a task fedora-latest/test_commands for PR#881.
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: __main__: fedora-latest/test_commands PR#881 is successfully locked.
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: __main__: Available resources: 0 CPU, 104.0234375MB
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: RunPytest
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: root: Initializing job 06e12b4a-ac68-11eb-ab19-fa163e979771
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: VagrantBoxDownload
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: VagrantUp
May 03 23:33:55 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "vagrant up --no-provision --parallel"
...
May 03 23:38:28 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "vagrant ssh -c IPATEST_YAML_CONFIG=/vagrant/ipa-test-config.yaml ipa>
...
May 04 00:31:33 permanent-small-runner-2 bash[1675771]: DEBUG: root: -------------------- generated xml file: /vagrant/junit.xml --------------------
May 04 00:31:33 permanent-small-runner-2 bash[1675771]: DEBUG: root: --------------- generated html file: file:///vagrant/report.html ---------------
May 04 00:31:33 permanent-small-runner-2 bash[1675771]: DEBUG: root: ================= 36 passed, 3 warnings in 3176.97s (0:52:56) ==================
May 04 00:31:35 permanent-small-runner-2 bash[1675771]: INFO: root: >>>>> TESTS PASSED <<<<<<
May 04 00:31:35 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: VagrantCleanup
May 04 00:31:35 permanent-small-runner-2 bash[1675771]: INFO: root: Destroying vagrant machines.
May 04 00:31:35 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "vagrant destroy --force"
May 04 00:31:39 permanent-small-runner-2 bash[1675771]: DEBUG: root: ==> client0: Removing domain...
May 04 00:31:40 permanent-small-runner-2 bash[1675771]: DEBUG: root: ==> replica0: Removing domain...
May 04 00:31:41 permanent-small-runner-2 bash[1675771]: DEBUG: root: ==> master: Removing domain...
May 04 00:31:41 permanent-small-runner-2 bash[1675771]: DEBUG: root: ==> controller: Removing domain...
May 04 00:31:42 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "find /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e979771 ->
May 04 00:32:34 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: CloudUpload
May 04 00:32:53 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e9>
May 04 00:32:56 permanent-small-runner-2 bash[1675771]: [262B blob data]
May 04 00:32:56 permanent-small-runner-2 bash[1675771]: [340B blob data]
May 04 00:32:56 permanent-small-runner-2 bash[1675771]: [314B blob data]
May 04 00:32:56 permanent-small-runner-2 bash[1675771]: [320B blob data]
May 04 00:32:56 permanent-small-runner-2 bash[1675771]: [330B blob data]
...
May 04 00:33:17 permanent-small-runner-2 bash[1675771]: [422B blob data]
May 04 00:33:17 permanent-small-runner-2 bash[1675771]: [420B blob data]
May 04 00:33:17 permanent-small-runner-2 bash[1675771]: [238B blob data]
May 04 00:33:18 permanent-small-runner-2 bash[1675771]: [418B blob data]
May 04 00:33:18 permanent-small-runner-2 bash[1675771]: INFO: root: Executing: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e9>
May 04 00:33:20 permanent-small-runner-2 bash[1675771]: [202B blob data]
May 04 00:33:21 permanent-small-runner-2 bash[1675771]: [480B blob data]
May 04 00:33:21 permanent-small-runner-2 bash[1675771]: [363B blob data]
May 04 00:33:21 permanent-small-runner-2 bash[1675771]: [532B blob data]
May 04 00:33:21 permanent-small-runner-2 bash[1675771]: [361B blob data]
May 04 00:33:21 permanent-small-runner-2 bash[1675771]: [464B blob data]
...
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: [510B blob data]
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: [504B blob data]
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: [550B blob data]
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: [552B blob data]
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: CRITICAL: root: Terminating execution, runtime exceeded 3600s
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: [273B blob data]
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: root: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e979771 s3:/>
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: Traceback (most recent call last):
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise self.exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self._run()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 179, in _run
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise PopenException(self)
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: tasks.common.PopenException: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-f>
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: root: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e979771 s3:/>
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: Traceback (most recent call last):
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise self.exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self._run()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/remote_storage.py", line 212, in _run
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self.execute_subtask(PopenTask(aws_sync_cmd + sync_gz))
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 80, in execute_subtask
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     task()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 139, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise self.exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self._run()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 179, in _run
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise PopenException(self)
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: tasks.common.PopenException: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-f>
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: root: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-fa163e979771 s3:/>
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: Traceback (most recent call last):
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/tasks.py", line 118, in upload_artifacts
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self.execute_subtask(
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 80, in execute_subtask
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     task()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 139, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise self.exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self._run()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/remote_storage.py", line 212, in _run
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self.execute_subtask(PopenTask(aws_sync_cmd + sync_gz))
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 80, in execute_subtask
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     task()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 139, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 122, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise self.exc
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 105, in __target
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     self._run()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 179, in _run
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise PopenException(self)
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: tasks.common.PopenException: Process "aws s3 sync /root/freeipa-pr-ci/jobs/06e12b4a-ac68-11eb-ab19-f>
May 04 00:33:55 permanent-small-runner-2 systemd[1]: Stopping FreeIPA PR CI...
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: root: RunPytest timed out after 3600s
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: Traceback (most recent call last):
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 135, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     super(FallibleTask, self).__call__()
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:   File "/root/freeipa-pr-ci/tasks/common.py", line 119, in __call__
May 04 00:33:55 permanent-small-runner-2 bash[1675771]:     raise TimeoutException(self)
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: tasks.common.TimeoutException: RunPytest timed out after 3600s
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: raven.base.Client: Configuring Raven for host: https://sentry.io
May 04 00:33:55 permanent-small-runner-2 bash[1675771]: DEBUG: raven.base.Client: Sending message of length 1412 to https://sentry.io/api/193222/store/
May 04 00:34:04 permanent-small-runner-2 bash[1675771]: INFO: root: Destroying all libvirt domains.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: State 'stop-sigterm' timed out. Killing.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Killing process 1675771 (prci.py) with signal SIGKILL.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Killing process 1752174 (virsh) with signal SIGKILL.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Killing process 1752173 (prci.py) with signal SIGKILL.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Killing process 1752175 (virsh) with signal SIGKILL.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Main process exited, code=killed, status=9/KILL
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Failed with result 'timeout'.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: Stopped FreeIPA PR CI.
May 04 00:35:25 permanent-small-runner-2 systemd[1]: prci.service: Consumed 21min 15.609s CPU time.
May 04 07:00:05 permanent-small-runner-2 systemd[1]: Started FreeIPA PR CI.
May 04 07:00:05 permanent-small-runner-2 bash[1752741]: INFO: __main__: Checking pending pull requests.