2025-12-26 00:06:49.694486 | Job console starting... 2025-12-26 00:06:49.704332 | Updating repositories 2025-12-26 00:06:50.223703 | Preparing job workspace 2025-12-26 00:06:58.931427 | Running Ansible setup... 2025-12-26 00:07:03.498279 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-26 00:07:04.231173 | 2025-12-26 00:07:04.231295 | PLAY [localhost] 2025-12-26 00:07:04.240263 | 2025-12-26 00:07:04.240349 | TASK [Gathering Facts] 2025-12-26 00:07:05.192761 | localhost | ok 2025-12-26 00:07:05.223527 | 2025-12-26 00:07:05.223749 | TASK [Setup log path fact] 2025-12-26 00:07:05.249868 | localhost | ok 2025-12-26 00:07:05.277091 | 2025-12-26 00:07:05.277211 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-26 00:07:05.306578 | localhost | ok 2025-12-26 00:07:05.316899 | 2025-12-26 00:07:05.316988 | TASK [emit-job-header : Print job information] 2025-12-26 00:07:05.356390 | # Job Information 2025-12-26 00:07:05.356569 | Ansible Version: 2.15.12 2025-12-26 00:07:05.356614 | Job: ansible-test-sanity-docker-devel 2025-12-26 00:07:05.356643 | Pipeline: periodic 2025-12-26 00:07:05.356670 | Executor: ze01.softwarefactory-project.io 2025-12-26 00:07:05.356697 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-26 00:07:05.356729 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/456/ansible/456bc43d080942858221a173c15e28fb/ 2025-12-26 00:07:05.356756 | Event ID: 251d181dbd134356bcf2e7a38c8ef353 2025-12-26 00:07:05.361936 | 2025-12-26 00:07:05.362048 | LOOP [emit-job-header : Print node information] 2025-12-26 00:07:05.484298 | localhost | ok: 2025-12-26 00:07:05.484470 | localhost | # Node Information 2025-12-26 00:07:05.484510 | localhost | Inventory Hostname: controller 2025-12-26 00:07:05.484540 | localhost | Hostname: np0005570828 2025-12-26 00:07:05.484568 | localhost | Username: zuul 2025-12-26 00:07:05.484601 | localhost | Distro: Fedora 37 2025-12-26 00:07:05.484629 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-26 00:07:05.484655 | localhost | Region: ca-ymq-1 2025-12-26 00:07:05.484680 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-26 00:07:05.484705 | localhost | Product Name: OpenStack Nova 2025-12-26 00:07:05.484729 | localhost | Interface IP: 162.253.55.204 2025-12-26 00:07:05.497201 | 2025-12-26 00:07:05.497280 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-26 00:07:05.906909 | localhost -> localhost | changed 2025-12-26 00:07:05.912641 | 2025-12-26 00:07:05.912709 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-26 00:07:07.294598 | localhost -> localhost | changed 2025-12-26 00:07:07.352591 | 2025-12-26 00:07:07.352777 | PLAY [all:!appliance*] 2025-12-26 00:07:07.386530 | 2025-12-26 00:07:07.386638 | TASK [include_role : start-zuul-console] 2025-12-26 00:07:07.411182 | controller | ok 2025-12-26 00:07:07.431072 | 2025-12-26 00:07:07.431176 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-26 00:07:07.856091 | controller | ok 2025-12-26 00:07:07.867482 | 2025-12-26 00:07:07.867564 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-26 00:07:08.747463 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-26 00:07:08.755210 | 2025-12-26 00:07:08.755271 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-26 00:07:09.321625 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.332219 | 2025-12-26 00:07:09.332307 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-26 00:07:09.357043 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.368921 | 2025-12-26 00:07:09.369055 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-26 00:07:09.393658 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.402326 | 2025-12-26 00:07:09.402411 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-26 00:07:09.426156 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.432459 | 2025-12-26 00:07:09.432564 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-26 00:07:09.445932 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.453848 | 2025-12-26 00:07:09.453942 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-26 00:07:09.467632 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.485380 | 2025-12-26 00:07:09.485559 | TASK [Disable Fedora Modular] 2025-12-26 00:07:09.739297 | controller | changed 2025-12-26 00:07:09.752575 | 2025-12-26 00:07:09.752780 | TASK [Enable EPEL] 2025-12-26 00:07:09.779597 | controller | skipping: Conditional result was False 2025-12-26 00:07:09.794005 | 2025-12-26 00:07:09.794499 | TASK [Register the RHEL node] 2025-12-26 00:07:10.352590 | 2025-12-26 00:07:10.352750 | TASK [Show the subscription-manager status] 2025-12-26 00:07:10.928743 | controller | skipping: Conditional result was False 2025-12-26 00:07:10.943869 | 2025-12-26 00:07:10.944053 | TASK [Enable EPEL on RHEL] 2025-12-26 00:07:11.501705 | controller | skipping: Conditional result was False 2025-12-26 00:07:11.508048 | 2025-12-26 00:07:11.508120 | TASK [Install git and tox] 2025-12-26 00:08:37.960229 | controller | changed 2025-12-26 00:08:37.976408 | 2025-12-26 00:08:37.976547 | TASK [include_role : prepare-workspace] 2025-12-26 00:08:38.015989 | controller | ok 2025-12-26 00:08:38.052640 | 2025-12-26 00:08:38.052757 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-26 00:08:38.308864 | controller | ok 2025-12-26 00:08:38.315668 | 2025-12-26 00:08:38.315777 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-26 00:08:53.262129 | controller | Output suppressed because no_log was given 2025-12-26 00:08:53.272190 | 2025-12-26 00:08:53.272252 | TASK [include_role : prepare-workspace-openshift] 2025-12-26 00:08:53.298716 | controller | skipping: Conditional result was False 2025-12-26 00:08:53.321976 | 2025-12-26 00:08:53.322062 | PLAY [all:!appliance] 2025-12-26 00:08:53.338529 | 2025-12-26 00:08:53.338627 | TASK [Run add-build-sshkey role (RSA)] 2025-12-26 00:08:53.369267 | controller | ok 2025-12-26 00:08:53.386077 | 2025-12-26 00:08:53.386188 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-26 00:08:53.635101 | controller -> localhost | ok 2025-12-26 00:08:53.642901 | 2025-12-26 00:08:53.642986 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-26 00:08:53.663938 | controller | ok 2025-12-26 00:08:53.679570 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-26 00:08:53.687509 | 2025-12-26 00:08:53.687600 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-26 00:08:54.172289 | controller -> localhost | Generating public/private rsa key pair. 2025-12-26 00:08:54.172523 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_rsa. 2025-12-26 00:08:54.172553 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_rsa.pub. 2025-12-26 00:08:54.172576 | controller -> localhost | The key fingerprint is: 2025-12-26 00:08:54.172597 | controller -> localhost | SHA256:Hj+z+ULzhCt5W1Ry1/4eeURbPzQ6n5wKuqXntDdtcFk zuul-build-sshkey 2025-12-26 00:08:54.172616 | controller -> localhost | The key's randomart image is: 2025-12-26 00:08:54.172635 | controller -> localhost | +---[RSA 2048]----+ 2025-12-26 00:08:54.172653 | controller -> localhost | | | 2025-12-26 00:08:54.172672 | controller -> localhost | | .| 2025-12-26 00:08:54.172689 | controller -> localhost | | . oo=| 2025-12-26 00:08:54.172707 | controller -> localhost | | +o+E| 2025-12-26 00:08:54.172724 | controller -> localhost | | S ..o o*| 2025-12-26 00:08:54.172750 | controller -> localhost | | . o+...++*| 2025-12-26 00:08:54.172772 | controller -> localhost | | .o+O. +Bo| 2025-12-26 00:08:54.172791 | controller -> localhost | | o OB+o.+o| 2025-12-26 00:08:54.172810 | controller -> localhost | | *B*o.o .| 2025-12-26 00:08:54.172830 | controller -> localhost | +----[SHA256]-----+ 2025-12-26 00:08:54.172882 | controller -> localhost | ok: Runtime: 0:00:00.148372 2025-12-26 00:08:54.181889 | 2025-12-26 00:08:54.182042 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-26 00:08:54.207258 | controller | ok 2025-12-26 00:08:54.221565 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-26 00:08:54.232434 | 2025-12-26 00:08:54.232498 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-26 00:08:54.247292 | controller | skipping: Conditional result was False 2025-12-26 00:08:54.256057 | 2025-12-26 00:08:54.256142 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-26 00:08:55.019294 | controller | changed 2025-12-26 00:08:55.025932 | 2025-12-26 00:08:55.026005 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-26 00:08:56.103620 | controller | ok 2025-12-26 00:08:56.119298 | 2025-12-26 00:08:56.119445 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-26 00:08:56.767999 | controller | changed 2025-12-26 00:08:56.776114 | 2025-12-26 00:08:56.776199 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-26 00:08:59.360548 | controller | changed 2025-12-26 00:08:59.368737 | 2025-12-26 00:08:59.368823 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-26 00:08:59.393560 | controller | skipping: Conditional result was False 2025-12-26 00:08:59.404633 | 2025-12-26 00:08:59.404776 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-26 00:08:59.900268 | controller -> localhost | changed 2025-12-26 00:08:59.917068 | 2025-12-26 00:08:59.917186 | TASK [add-build-sshkey : Add back temp key] 2025-12-26 00:09:00.286309 | controller -> localhost | Identity added: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_rsa (zuul-build-sshkey) 2025-12-26 00:09:00.286539 | controller -> localhost | ok: Runtime: 0:00:00.010232 2025-12-26 00:09:00.295363 | 2025-12-26 00:09:00.295449 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-26 00:09:00.645572 | controller | ok 2025-12-26 00:09:00.654543 | 2025-12-26 00:09:00.654677 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-26 00:09:00.685381 | controller | skipping: Conditional result was False 2025-12-26 00:09:00.704345 | 2025-12-26 00:09:00.704473 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-26 00:09:00.739107 | controller | ok 2025-12-26 00:09:00.771771 | 2025-12-26 00:09:00.771925 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-26 00:09:01.044803 | controller -> localhost | ok 2025-12-26 00:09:01.056365 | 2025-12-26 00:09:01.056509 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-26 00:09:01.085941 | controller | ok 2025-12-26 00:09:01.105984 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-26 00:09:01.118562 | 2025-12-26 00:09:01.118697 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-26 00:09:01.380782 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-26 00:09:01.381009 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_ecdsa. 2025-12-26 00:09:01.381066 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_ecdsa.pub. 2025-12-26 00:09:01.381106 | controller -> localhost | The key fingerprint is: 2025-12-26 00:09:01.381131 | controller -> localhost | SHA256:/g3hlbjLvNdVjjv/X5WWrEwR33PMvdUde9BXYlH10VE zuul-build-sshkey 2025-12-26 00:09:01.381155 | controller -> localhost | The key's randomart image is: 2025-12-26 00:09:01.381179 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-26 00:09:01.381201 | controller -> localhost | | .=BE| 2025-12-26 00:09:01.381223 | controller -> localhost | | .o=&| 2025-12-26 00:09:01.381245 | controller -> localhost | | . +&| 2025-12-26 00:09:01.381267 | controller -> localhost | | . .o X| 2025-12-26 00:09:01.381289 | controller -> localhost | | S o o. Oo| 2025-12-26 00:09:01.381310 | controller -> localhost | | . . +o + +| 2025-12-26 00:09:01.381331 | controller -> localhost | | . + + o.| 2025-12-26 00:09:01.381352 | controller -> localhost | | + +. + .| 2025-12-26 00:09:01.381374 | controller -> localhost | | *o. o*| 2025-12-26 00:09:01.381395 | controller -> localhost | +----[SHA256]-----+ 2025-12-26 00:09:01.381454 | controller -> localhost | ok: Runtime: 0:00:00.010726 2025-12-26 00:09:01.389445 | 2025-12-26 00:09:01.389528 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-26 00:09:01.418604 | controller | ok 2025-12-26 00:09:01.432781 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-26 00:09:01.442733 | 2025-12-26 00:09:01.442822 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-26 00:09:01.466903 | controller | skipping: Conditional result was False 2025-12-26 00:09:01.475407 | 2025-12-26 00:09:01.475631 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-26 00:09:01.776279 | controller | changed 2025-12-26 00:09:01.791844 | 2025-12-26 00:09:01.791992 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-26 00:09:02.080821 | controller | ok 2025-12-26 00:09:02.088266 | 2025-12-26 00:09:02.088391 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-26 00:09:02.771901 | controller | changed 2025-12-26 00:09:02.780605 | 2025-12-26 00:09:02.780699 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-26 00:09:03.445078 | controller | changed 2025-12-26 00:09:03.451057 | 2025-12-26 00:09:03.451120 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-26 00:09:03.475510 | controller | skipping: Conditional result was False 2025-12-26 00:09:03.482722 | 2025-12-26 00:09:03.482784 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-26 00:09:03.722629 | controller -> localhost | changed 2025-12-26 00:09:03.735464 | 2025-12-26 00:09:03.735579 | TASK [add-build-sshkey : Add back temp key] 2025-12-26 00:09:03.997632 | controller -> localhost | Identity added: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/456bc43d080942858221a173c15e28fb_id_ecdsa (zuul-build-sshkey) 2025-12-26 00:09:03.997817 | controller -> localhost | ok: Runtime: 0:00:00.006670 2025-12-26 00:09:04.004382 | 2025-12-26 00:09:04.004447 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-26 00:09:04.226797 | controller | ok 2025-12-26 00:09:04.232450 | 2025-12-26 00:09:04.232512 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-26 00:09:04.256497 | controller | skipping: Conditional result was False 2025-12-26 00:09:04.269057 | 2025-12-26 00:09:04.269146 | TASK [include_role : remove-zuul-sshkey] 2025-12-26 00:09:04.282780 | controller | skipping: Conditional result was False 2025-12-26 00:09:04.290233 | 2025-12-26 00:09:04.290323 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-26 00:09:04.511505 | controller | ok: "logs" 2025-12-26 00:09:04.511817 | controller | ok: All items complete 2025-12-26 00:09:04.511858 | 2025-12-26 00:09:04.711862 | controller | ok: "artifacts" 2025-12-26 00:09:04.908570 | controller | ok: "docs" 2025-12-26 00:09:04.926138 | 2025-12-26 00:09:04.926272 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-26 00:09:05.155810 | controller | changed: "logs" 2025-12-26 00:09:05.356300 | controller | changed: "artifacts" 2025-12-26 00:09:05.560638 | controller | changed: "docs" 2025-12-26 00:09:05.625739 | 2025-12-26 00:09:05.625866 | PLAY RECAP 2025-12-26 00:09:05.625925 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-26 00:09:05.625963 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-26 00:09:05.625991 | 2025-12-26 00:09:05.750449 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-26 00:09:05.751683 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-26 00:09:06.411109 | 2025-12-26 00:09:06.411268 | PLAY [all] 2025-12-26 00:09:06.435511 | 2025-12-26 00:09:06.435658 | TASK [Install binary dependencies] 2025-12-26 00:09:06.485834 | controller | ok 2025-12-26 00:09:06.509587 | 2025-12-26 00:09:06.509739 | TASK [bindep : Include find tasks] 2025-12-26 00:09:06.561232 | controller | ok 2025-12-26 00:09:06.569162 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-26 00:09:06.575812 | 2025-12-26 00:09:06.575926 | TASK [bindep : Look for bindep.txt] 2025-12-26 00:09:06.990232 | controller | ok 2025-12-26 00:09:07.004991 | 2025-12-26 00:09:07.005239 | TASK [bindep : Define bindep_file fact] 2025-12-26 00:09:07.031082 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.039603 | 2025-12-26 00:09:07.039737 | TASK [bindep : Look for other-requirements.txt] 2025-12-26 00:09:07.260232 | controller | ok 2025-12-26 00:09:07.272664 | 2025-12-26 00:09:07.272852 | TASK [bindep : Define bindep_file fact] 2025-12-26 00:09:07.299259 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.316260 | 2025-12-26 00:09:07.316467 | TASK [bindep : Look for bindep fallback file] 2025-12-26 00:09:07.354382 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.363829 | 2025-12-26 00:09:07.363960 | TASK [bindep : Define bindep_file fact] 2025-12-26 00:09:07.389429 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.400806 | 2025-12-26 00:09:07.400955 | TASK [bindep : Include bindep tasks] 2025-12-26 00:09:07.426915 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.433510 | 2025-12-26 00:09:07.433584 | TASK [bindep : Include install tasks] 2025-12-26 00:09:07.457464 | controller | skipping: Conditional result was False 2025-12-26 00:09:07.464079 | 2025-12-26 00:09:07.464150 | LOOP [bindep : Include package tasks] 2025-12-26 00:09:07.520355 | 2025-12-26 00:09:07.520595 | TASK [Run test-setup role] 2025-12-26 00:09:07.541720 | controller | ok 2025-12-26 00:09:07.561409 | 2025-12-26 00:09:07.561551 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-26 00:09:07.787657 | controller | ok 2025-12-26 00:09:07.803085 | 2025-12-26 00:09:07.803253 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-26 00:09:08.348959 | controller | skipping: Conditional result was False 2025-12-26 00:09:08.405850 | 2025-12-26 00:09:08.405953 | PLAY RECAP 2025-12-26 00:09:08.406008 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-26 00:09:08.406077 | 2025-12-26 00:09:08.511578 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-26 00:09:08.512603 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-26 00:09:09.139038 | 2025-12-26 00:09:09.139180 | PLAY [controller] 2025-12-26 00:09:09.160360 | 2025-12-26 00:09:09.160477 | TASK [Create the /root directory] 2025-12-26 00:09:09.587007 | controller | ok 2025-12-26 00:09:09.603506 | 2025-12-26 00:09:09.603747 | TASK [Install glibc-langpack-en] 2025-12-26 00:09:13.620738 | controller | ok: Nothing to do 2025-12-26 00:09:13.626676 | 2025-12-26 00:09:13.626760 | TASK [Ensure controller directory exists] 2025-12-26 00:09:13.830142 | controller | changed 2025-12-26 00:09:13.837043 | 2025-12-26 00:09:13.837117 | TASK [Install container runtime] 2025-12-26 00:09:13.876874 | controller | ok 2025-12-26 00:09:13.913704 | 2025-12-26 00:09:13.913818 | LOOP [ensure-podman : Find distribution installation] 2025-12-26 00:09:13.944668 | controller | ok: "/var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-26 00:09:13.960256 | controller | included: /var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-26 00:09:13.968539 | 2025-12-26 00:09:13.968647 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-26 00:10:19.937183 | controller | changed 2025-12-26 00:10:19.943946 | 2025-12-26 00:10:19.944009 | TASK [ensure-podman : Fetch podman version] 2025-12-26 00:10:20.516394 | controller | Client: Podman Engine 2025-12-26 00:10:20.543755 | controller | Version: 4.6.2 2025-12-26 00:10:20.543788 | controller | API Version: 4.6.2 2025-12-26 00:10:20.543794 | controller | Go Version: go1.19.12 2025-12-26 00:10:20.543824 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-26 00:10:20.543831 | controller | OS/Arch: linux/amd64 2025-12-26 00:10:20.978195 | controller | ok: Runtime: 0:00:00.217221 2025-12-26 00:10:20.993290 | 2025-12-26 00:10:20.993523 | TASK [ensure-podman : Print podman version installed] 2025-12-26 00:10:21.033962 | Podman version: Client: Podman Engine 2025-12-26 00:10:21.034288 | Version: 4.6.2 2025-12-26 00:10:21.034354 | API Version: 4.6.2 2025-12-26 00:10:21.034401 | Go Version: go1.19.12 2025-12-26 00:10:21.034443 | Built: Mon Aug 28 19:38:31 2023 2025-12-26 00:10:21.034489 | OS/Arch: linux/amd64 2025-12-26 00:10:21.047705 | 2025-12-26 00:10:21.047835 | TASK [ensure-podman : Validate podman engine] 2025-12-26 00:10:21.598883 | controller | skipping: Conditional result was False 2025-12-26 00:10:21.607917 | 2025-12-26 00:10:21.608090 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-26 00:10:21.633127 | controller | skipping: Conditional result was False 2025-12-26 00:10:21.654718 | 2025-12-26 00:10:21.654828 | TASK [Ensure python3.8 is present] 2025-12-26 00:10:21.670132 | controller | skipping: Conditional result was False 2025-12-26 00:10:21.678617 | 2025-12-26 00:10:21.678759 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-26 00:10:21.701585 | controller | ok 2025-12-26 00:10:21.723381 | 2025-12-26 00:10:21.723531 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-26 00:10:23.157526 | controller | ok: Nothing to do 2025-12-26 00:10:23.174805 | 2025-12-26 00:10:23.175073 | TASK [our-ensure-python : Also install python3-devel] 2025-12-26 00:10:32.497639 | controller | changed 2025-12-26 00:10:32.514813 | 2025-12-26 00:10:32.515078 | TASK [Run ensure-virtualenv role] 2025-12-26 00:10:32.537802 | controller | ok 2025-12-26 00:10:32.569462 | 2025-12-26 00:10:32.569627 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-26 00:10:32.816399 | controller | /usr/bin/virtualenv 2025-12-26 00:10:33.138612 | controller | ok: Runtime: 0:00:00.005438 2025-12-26 00:10:33.145322 | 2025-12-26 00:10:33.145404 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-26 00:10:33.181212 | controller | skipping: Conditional result was False 2025-12-26 00:10:33.181472 | controller | ok: All items complete 2025-12-26 00:10:33.181499 | 2025-12-26 00:10:33.203154 | 2025-12-26 00:10:33.203265 | TASK [Find the full path of the Python interpreter] 2025-12-26 00:10:33.438385 | controller | /usr/bin/python3 2025-12-26 00:10:33.739897 | controller | ok 2025-12-26 00:10:33.746186 | 2025-12-26 00:10:33.746291 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-26 00:10:34.660142 | controller | created virtual environment CPython3.11.0.final.0-64 in 528ms 2025-12-26 00:10:34.681459 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-26 00:10:34.681494 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-12-26 00:10:34.681506 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-26 00:10:34.681519 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-26 00:10:34.801615 | controller | changed 2025-12-26 00:10:34.815895 | 2025-12-26 00:10:34.816083 | TASK [Set selinux package] 2025-12-26 00:10:34.856550 | controller | ok 2025-12-26 00:10:34.869891 | 2025-12-26 00:10:34.870144 | TASK [Set selinux package (Fedora)] 2025-12-26 00:10:34.929668 | controller | ok 2025-12-26 00:10:34.943900 | 2025-12-26 00:10:34.943997 | TASK [Install selinux into virtualenv] 2025-12-26 00:11:24.339375 | controller | Collecting selinux-please-lie-to-me 2025-12-26 00:11:36.610424 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-26 00:11:36.930641 | controller | Collecting setuptools<50.0.0 2025-12-26 00:11:36.937341 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-26 00:11:36.985509 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.0 MB/s eta 0:00:00 2025-12-26 00:11:37.069895 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-26 00:11:37.070110 | controller | Attempting uninstall: setuptools 2025-12-26 00:11:37.072518 | controller | Found existing installation: setuptools 62.6.0 2025-12-26 00:11:37.165136 | controller | Uninstalling setuptools-62.6.0: 2025-12-26 00:11:37.178455 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-26 00:11:37.549825 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-26 00:11:48.978928 | controller | 2025-12-26 00:11:49.121511 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-26 00:11:49.121580 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-26 00:11:49.551607 | controller | ok: Runtime: 0:01:13.951166 2025-12-26 00:11:49.558571 | 2025-12-26 00:11:49.558690 | TASK [Install pytest-forked into virtualenv] 2025-12-26 00:12:01.259256 | controller | Collecting pytest-forked 2025-12-26 00:12:10.399829 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-26 00:12:10.445587 | controller | Collecting py 2025-12-26 00:12:10.456640 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-26 00:12:10.472252 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 7.3 MB/s eta 0:00:00 2025-12-26 00:12:10.586072 | controller | Collecting pytest>=3.10 2025-12-26 00:12:10.592509 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-26 00:12:10.610798 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 27.6 MB/s eta 0:00:00 2025-12-26 00:12:10.652185 | controller | Collecting iniconfig>=1.0.1 2025-12-26 00:12:10.655612 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-26 00:12:10.699612 | controller | Collecting packaging>=22 2025-12-26 00:12:10.702803 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-26 00:12:10.709725 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 14.5 MB/s eta 0:00:00 2025-12-26 00:12:10.744150 | controller | Collecting pluggy<2,>=1.5 2025-12-26 00:12:10.747619 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-26 00:12:10.794827 | controller | Collecting pygments>=2.7.2 2025-12-26 00:12:10.798023 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-26 00:12:10.823231 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 66.7 MB/s eta 0:00:00 2025-12-26 00:12:10.891880 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-26 00:12:12.024978 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-26 00:12:12.034782 | controller | 2025-12-26 00:12:12.142890 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-26 00:12:12.142946 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-26 00:12:12.618601 | controller | ok: Runtime: 0:00:22.379082 2025-12-26 00:12:12.632993 | 2025-12-26 00:12:12.633167 | TASK [Update pip] 2025-12-26 00:12:13.190792 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-26 00:12:46.674950 | controller | Collecting pip 2025-12-26 00:13:10.991606 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-26 00:13:11.053064 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.5 MB/s eta 0:00:00 2025-12-26 00:13:11.116590 | controller | Installing collected packages: pip 2025-12-26 00:13:11.116721 | controller | Attempting uninstall: pip 2025-12-26 00:13:11.118927 | controller | Found existing installation: pip 22.2.2 2025-12-26 00:13:11.256883 | controller | Uninstalling pip-22.2.2: 2025-12-26 00:13:11.272959 | controller | Successfully uninstalled pip-22.2.2 2025-12-26 00:13:12.099875 | controller | Successfully installed pip-25.3 2025-12-26 00:13:12.237090 | controller | ok: Runtime: 0:00:59.313158 2025-12-26 00:13:12.245630 | 2025-12-26 00:13:12.245733 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-26 00:13:12.480322 | controller | changed 2025-12-26 00:13:12.486362 | 2025-12-26 00:13:12.486425 | TASK [Install ansible into virtualenv] 2025-12-26 00:13:12.989693 | controller | Processing ./src/github.com/ansible/ansible 2025-12-26 00:13:12.992997 | controller | Installing build dependencies: started 2025-12-26 00:13:50.153204 | controller | Installing build dependencies: finished with status 'done' 2025-12-26 00:13:50.153778 | controller | Getting requirements to build wheel: started 2025-12-26 00:13:50.925722 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-26 00:13:50.927227 | controller | Preparing metadata (pyproject.toml): started 2025-12-26 00:13:51.434663 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-26 00:13:51.440121 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-12-26 00:13:51.445173 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-26 00:13:51.543896 | controller | ERROR 2025-12-26 00:13:51.544073 | controller | { 2025-12-26 00:13:51.544120 | controller | "delta": "0:00:38.805226", 2025-12-26 00:13:51.544149 | controller | "end": "2025-12-26 00:13:51.505497", 2025-12-26 00:13:51.544174 | controller | "msg": "non-zero return code", 2025-12-26 00:13:51.544208 | controller | "rc": 1, 2025-12-26 00:13:51.544233 | controller | "start": "2025-12-26 00:13:12.700271" 2025-12-26 00:13:51.544256 | controller | } failure 2025-12-26 00:13:51.545898 | 2025-12-26 00:13:51.545963 | PLAY RECAP 2025-12-26 00:13:51.546062 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-26 00:13:51.546102 | 2025-12-26 00:13:51.671294 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-26 00:13:51.672750 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-26 00:13:52.283126 | 2025-12-26 00:13:52.283231 | PLAY [all] 2025-12-26 00:13:52.305404 | 2025-12-26 00:13:52.305558 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-26 00:13:52.560593 | controller | changed: non-zero return code 2025-12-26 00:13:52.566743 | 2025-12-26 00:13:52.566819 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-26 00:13:52.590978 | controller | skipping: Conditional result was False 2025-12-26 00:13:52.604617 | 2025-12-26 00:13:52.604766 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-26 00:13:52.645765 | 2025-12-26 00:13:52.646071 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-26 00:13:52.681669 | 2025-12-26 00:13:52.681883 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-26 00:13:52.707686 | controller | skipping: Conditional result was False 2025-12-26 00:13:52.716954 | 2025-12-26 00:13:52.717060 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-26 00:13:52.738196 | 2025-12-26 00:13:52.738353 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-26 00:13:52.751586 | controller | skipping: Conditional result was False 2025-12-26 00:13:52.758154 | 2025-12-26 00:13:52.758224 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-26 00:13:52.771330 | controller | skipping: Conditional result was False 2025-12-26 00:13:52.777937 | 2025-12-26 00:13:52.778010 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-26 00:13:52.791567 | controller | skipping: Conditional result was False 2025-12-26 00:13:52.818341 | 2025-12-26 00:13:52.818426 | PLAY RECAP 2025-12-26 00:13:52.818470 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-26 00:13:52.818489 | 2025-12-26 00:13:52.912488 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-26 00:13:52.913846 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-26 00:13:53.601332 | 2025-12-26 00:13:53.601492 | PLAY [all:!appliance*] 2025-12-26 00:13:53.635164 | 2025-12-26 00:13:53.635313 | TASK [unregister the node] 2025-12-26 00:13:54.168440 | controller | skipping: Conditional result was False 2025-12-26 00:13:54.175784 | 2025-12-26 00:13:54.175900 | TASK [include_role : fetch-output] 2025-12-26 00:13:54.232779 | controller | ok 2025-12-26 00:13:54.272145 | 2025-12-26 00:13:54.272280 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-26 00:13:54.319153 | controller | skipping: Conditional result was False 2025-12-26 00:13:54.346098 | 2025-12-26 00:13:54.346406 | TASK [fetch-output : Set log path for single node] 2025-12-26 00:13:54.386955 | controller | ok 2025-12-26 00:13:54.392856 | 2025-12-26 00:13:54.392926 | LOOP [fetch-output : Ensure local output dirs] 2025-12-26 00:13:54.785901 | controller -> localhost | ok: "/var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/logs" 2025-12-26 00:13:55.025882 | controller -> localhost | changed: "/var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/artifacts" 2025-12-26 00:13:55.301707 | controller -> localhost | changed: "/var/lib/zuul/builds/456bc43d080942858221a173c15e28fb/work/docs" 2025-12-26 00:13:55.318695 | 2025-12-26 00:13:55.318812 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-26 00:13:56.023000 | controller | changed: 2025-12-26 00:13:56.023500 | controller | .d..t...... ./ 2025-12-26 00:13:56.023560 | controller | cd+++++++++ controller/ 2025-12-26 00:13:56.023627 | controller | changed: All items complete 2025-12-26 00:13:56.023671 | 2025-12-26 00:13:56.567512 | controller | changed: .d..t...... ./ 2025-12-26 00:13:57.063379 | controller | changed: .d..t...... ./ 2025-12-26 00:13:57.082418 | 2025-12-26 00:13:57.082546 | TASK [include_role : fetch-output-openshift] 2025-12-26 00:13:57.098995 | controller | skipping: Conditional result was False 2025-12-26 00:13:57.108495 | 2025-12-26 00:13:57.108654 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-26 00:13:57.147619 | controller | skipping: Conditional result was False 2025-12-26 00:13:57.162855 | controller | skipping: Conditional result was False 2025-12-26 00:13:57.205281 | 2025-12-26 00:13:57.205495 | PLAY [localhost] 2025-12-26 00:13:57.221611 | 2025-12-26 00:13:57.221801 | TASK [Run Zuul manifest role] 2025-12-26 00:13:57.253888 | localhost | ok 2025-12-26 00:13:57.269945 | 2025-12-26 00:13:57.270111 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-26 00:13:57.684779 | localhost | changed 2025-12-26 00:13:57.700912 | 2025-12-26 00:13:57.701160 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-26 00:13:57.737372 | localhost | ok 2025-12-26 00:13:57.753356 | 2025-12-26 00:13:57.753599 | TASK [Set zuul-log-path fact] 2025-12-26 00:13:57.776837 | localhost | ok 2025-12-26 00:13:57.804940 | 2025-12-26 00:13:57.805110 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-26 00:13:57.845778 | localhost | ok 2025-12-26 00:13:57.854453 | 2025-12-26 00:13:57.854544 | LOOP [Run upload-logs-swift role] 2025-12-26 00:13:57.890042 | localhost | Output suppressed because no_log was given 2025-12-26 00:13:57.918449 | 2025-12-26 00:13:57.918580 | TASK [Set zuul-log-path fact] 2025-12-26 00:13:57.953954 | localhost | skipping: Conditional result was False 2025-12-26 00:13:57.960341 | 2025-12-26 00:13:57.960428 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-26 00:13:58.394484 | localhost -> localhost | ok: Runtime: 0:00:00.004685 2025-12-26 00:13:58.427977 | 2025-12-26 00:13:58.428110 | TASK [upload-logs-swift : Upload logs to swift]