2025-11-22 00:21:33.597710 | Job console starting...
2025-11-22 00:21:33.606762 | Updating repositories
2025-11-22 00:21:33.720538 | Preparing job workspace
2025-11-22 00:21:37.609911 | Running Ansible setup...
2025-11-22 00:21:42.413050 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-22 00:21:43.032334 | 
2025-11-22 00:21:43.032457 | PLAY [localhost]
2025-11-22 00:21:43.040843 | 
2025-11-22 00:21:43.040930 | TASK [Gathering Facts]
2025-11-22 00:21:43.962411 | localhost | ok
2025-11-22 00:21:43.977403 | 
2025-11-22 00:21:43.977501 | TASK [Setup log path fact]
2025-11-22 00:21:43.995543 | localhost | ok
2025-11-22 00:21:44.015544 | 
2025-11-22 00:21:44.015643 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-22 00:21:44.043723 | localhost | ok
2025-11-22 00:21:44.051452 | 
2025-11-22 00:21:44.051523 | TASK [emit-job-header : Print job information]
2025-11-22 00:21:44.102162 | # Job Information
2025-11-22 00:21:44.102412 | Ansible Version: 2.15.12
2025-11-22 00:21:44.102458 | Job: ansible-test-sanity-docker-devel
2025-11-22 00:21:44.102489 | Pipeline: periodic
2025-11-22 00:21:44.102523 | Executor: ze02.softwarefactory-project.io
2025-11-22 00:21:44.102583 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-22 00:21:44.102624 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/1d0/ansible/1d0f30ceb6734442bf4d12455afd6b1e/
2025-11-22 00:21:44.102654 | Event ID: c15ec521bc464be4b3ce046f0e5676a7
2025-11-22 00:21:44.109778 | 
2025-11-22 00:21:44.109905 | LOOP [emit-job-header : Print node information]
2025-11-22 00:21:44.239269 | localhost | ok:
2025-11-22 00:21:44.239483 | localhost | # Node Information
2025-11-22 00:21:44.239512 | localhost | Inventory Hostname: controller
2025-11-22 00:21:44.239531 | localhost | Hostname: np0005531624
2025-11-22 00:21:44.239551 | localhost | Username: zuul
2025-11-22 00:21:44.239574 | localhost | Distro: Fedora 37
2025-11-22 00:21:44.239593 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-22 00:21:44.239611 | localhost | Region: ca-ymq-1
2025-11-22 00:21:44.239628 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-22 00:21:44.239645 | localhost | Product Name: OpenStack Nova
2025-11-22 00:21:44.239677 | localhost | Interface IP: 162.253.55.213
2025-11-22 00:21:44.255246 | 
2025-11-22 00:21:44.255346 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-22 00:21:44.665969 | localhost -> localhost | changed
2025-11-22 00:21:44.674497 | 
2025-11-22 00:21:44.674600 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-22 00:21:45.508366 | localhost -> localhost | changed
2025-11-22 00:21:45.538095 | 
2025-11-22 00:21:45.538193 | PLAY [all:!appliance*]
2025-11-22 00:21:45.560081 | 
2025-11-22 00:21:45.560174 | TASK [include_role : start-zuul-console]
2025-11-22 00:21:45.582482 | controller | ok
2025-11-22 00:21:45.600995 | 
2025-11-22 00:21:45.601092 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-22 00:21:46.028862 | controller | ok
2025-11-22 00:21:46.039878 | 
2025-11-22 00:21:46.039997 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-22 00:21:46.858878 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-22 00:21:46.867923 | 
2025-11-22 00:21:46.868017 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-22 00:21:47.415697 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.423084 | 
2025-11-22 00:21:47.423192 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-22 00:21:47.447546 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.455019 | 
2025-11-22 00:21:47.455124 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-22 00:21:47.491214 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.505737 | 
2025-11-22 00:21:47.505922 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-22 00:21:47.533731 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.553361 | 
2025-11-22 00:21:47.553806 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-22 00:21:47.593292 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.611770 | 
2025-11-22 00:21:47.612037 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-22 00:21:47.636832 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.654866 | 
2025-11-22 00:21:47.655061 | TASK [Disable Fedora Modular]
2025-11-22 00:21:47.940527 | controller | changed
2025-11-22 00:21:47.955108 | 
2025-11-22 00:21:47.955327 | TASK [Enable EPEL]
2025-11-22 00:21:47.972854 | controller | skipping: Conditional result was False
2025-11-22 00:21:47.986386 | 
2025-11-22 00:21:47.986566 | TASK [Register the RHEL node]
2025-11-22 00:21:48.540152 | 
2025-11-22 00:21:48.540292 | TASK [Show the subscription-manager status]
2025-11-22 00:21:49.104719 | controller | skipping: Conditional result was False
2025-11-22 00:21:49.118552 | 
2025-11-22 00:21:49.118755 | TASK [Enable EPEL on RHEL]
2025-11-22 00:21:49.675997 | controller | skipping: Conditional result was False
2025-11-22 00:21:49.682228 | 
2025-11-22 00:21:49.682297 | TASK [Install git and tox]
2025-11-22 00:23:19.176836 | controller | changed
2025-11-22 00:23:19.193247 | 
2025-11-22 00:23:19.193435 | TASK [include_role : prepare-workspace]
2025-11-22 00:23:19.245709 | controller | ok
2025-11-22 00:23:19.284491 | 
2025-11-22 00:23:19.284628 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-22 00:23:19.543459 | controller | ok
2025-11-22 00:23:19.554576 | 
2025-11-22 00:23:19.554703 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-22 00:23:32.138536 | controller | Output suppressed because no_log was given
2025-11-22 00:23:32.153770 | 
2025-11-22 00:23:32.153927 | TASK [include_role : prepare-workspace-openshift]
2025-11-22 00:23:32.179964 | controller | skipping: Conditional result was False
2025-11-22 00:23:32.240350 | 
2025-11-22 00:23:32.240455 | PLAY [all:!appliance]
2025-11-22 00:23:32.257303 | 
2025-11-22 00:23:32.257423 | TASK [Run add-build-sshkey role (RSA)]
2025-11-22 00:23:32.300452 | controller | ok
2025-11-22 00:23:32.341531 | 
2025-11-22 00:23:32.341827 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-22 00:23:32.582841 | controller -> localhost | ok
2025-11-22 00:23:32.592434 | 
2025-11-22 00:23:32.592558 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-22 00:23:32.616155 | controller | ok
2025-11-22 00:23:32.637500 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-22 00:23:32.646656 | 
2025-11-22 00:23:32.646789 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-22 00:23:33.059887 | controller -> localhost | Generating public/private rsa key pair.
2025-11-22 00:23:33.060098 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_rsa.
2025-11-22 00:23:33.060129 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_rsa.pub.
2025-11-22 00:23:33.060153 | controller -> localhost | The key fingerprint is:
2025-11-22 00:23:33.060173 | controller -> localhost | SHA256:x9Ej9JLhcPZ5JcCLV27ATFblb80d3H4CPFGpUiGArfg zuul-build-sshkey
2025-11-22 00:23:33.060192 | controller -> localhost | The key's randomart image is:
2025-11-22 00:23:33.060210 | controller -> localhost | +---[RSA 2048]----+
2025-11-22 00:23:33.060228 | controller -> localhost | |       oo.*=*=+oo|
2025-11-22 00:23:33.060246 | controller -> localhost | |      . .* X*o++.|
2025-11-22 00:23:33.060264 | controller -> localhost | |     . .  *oX*.oo|
2025-11-22 00:23:33.060289 | controller -> localhost | |    . .  .o++=oo=|
2025-11-22 00:23:33.060317 | controller -> localhost | |     .  S oo .. O|
2025-11-22 00:23:33.060368 | controller -> localhost | |      E  .     o.|
2025-11-22 00:23:33.060407 | controller -> localhost | |                 |
2025-11-22 00:23:33.060434 | controller -> localhost | |                 |
2025-11-22 00:23:33.060454 | controller -> localhost | |                 |
2025-11-22 00:23:33.060475 | controller -> localhost | +----[SHA256]-----+
2025-11-22 00:23:33.060523 | controller -> localhost | ok: Runtime: 0:00:00.037639
2025-11-22 00:23:33.067297 | 
2025-11-22 00:23:33.067488 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-22 00:23:33.088081 | controller | ok
2025-11-22 00:23:33.098626 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-22 00:23:33.109196 | 
2025-11-22 00:23:33.109291 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-22 00:23:33.124106 | controller | skipping: Conditional result was False
2025-11-22 00:23:33.131346 | 
2025-11-22 00:23:33.131451 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-22 00:23:33.620050 | controller | changed
2025-11-22 00:23:33.634927 | 
2025-11-22 00:23:33.635113 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-22 00:23:33.878937 | controller | ok
2025-11-22 00:23:33.894651 | 
2025-11-22 00:23:33.894906 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-22 00:23:34.559815 | controller | changed
2025-11-22 00:23:34.572582 | 
2025-11-22 00:23:34.572800 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-22 00:23:35.222807 | controller | changed
2025-11-22 00:23:35.238253 | 
2025-11-22 00:23:35.238413 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-22 00:23:35.255005 | controller | skipping: Conditional result was False
2025-11-22 00:23:35.270728 | 
2025-11-22 00:23:35.270916 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-22 00:23:35.665854 | controller -> localhost | changed
2025-11-22 00:23:35.690880 | 
2025-11-22 00:23:35.691108 | TASK [add-build-sshkey : Add back temp key]
2025-11-22 00:23:36.065447 | controller -> localhost | Identity added: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_rsa (zuul-build-sshkey)
2025-11-22 00:23:36.065846 | controller -> localhost | ok: Runtime: 0:00:00.015037
2025-11-22 00:23:36.081286 | 
2025-11-22 00:23:36.081489 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-22 00:23:36.432241 | controller | ok
2025-11-22 00:23:36.443219 | 
2025-11-22 00:23:36.443348 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-22 00:23:36.468034 | controller | skipping: Conditional result was False
2025-11-22 00:23:36.479431 | 
2025-11-22 00:23:36.479518 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-22 00:23:36.509341 | controller | ok
2025-11-22 00:23:36.527237 | 
2025-11-22 00:23:36.527350 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-22 00:23:36.787927 | controller -> localhost | ok
2025-11-22 00:23:36.803741 | 
2025-11-22 00:23:36.803903 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-22 00:23:36.834073 | controller | ok
2025-11-22 00:23:36.861862 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-22 00:23:36.877843 | 
2025-11-22 00:23:36.877993 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-22 00:23:37.180750 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-22 00:23:37.181048 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_ecdsa.
2025-11-22 00:23:37.181115 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_ecdsa.pub.
2025-11-22 00:23:37.181208 | controller -> localhost | The key fingerprint is:
2025-11-22 00:23:37.181253 | controller -> localhost | SHA256:okaK1z4iiY/HLa02+vBCvyLN9Tsernb/dm7PQDw0ZQM zuul-build-sshkey
2025-11-22 00:23:37.181300 | controller -> localhost | The key's randomart image is:
2025-11-22 00:23:37.181349 | controller -> localhost | +---[ECDSA 521]---+
2025-11-22 00:23:37.181393 | controller -> localhost | |            E.+  |
2025-11-22 00:23:37.181428 | controller -> localhost | |             o . |
2025-11-22 00:23:37.181456 | controller -> localhost | |            o    |
2025-11-22 00:23:37.181485 | controller -> localhost | |           o .   |
2025-11-22 00:23:37.181512 | controller -> localhost | |    . . S   +    |
2025-11-22 00:23:37.181538 | controller -> localhost | | o +.. .   . .   |
2025-11-22 00:23:37.181565 | controller -> localhost | |==+++..     .    |
2025-11-22 00:23:37.181591 | controller -> localhost | |**X+=.+.  . oo   |
2025-11-22 00:23:37.181616 | controller -> localhost | |+O*B+=++.o.+..o  |
2025-11-22 00:23:37.181646 | controller -> localhost | +----[SHA256]-----+
2025-11-22 00:23:37.181783 | controller -> localhost | ok: Runtime: 0:00:00.007981
2025-11-22 00:23:37.194089 | 
2025-11-22 00:23:37.194255 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-22 00:23:37.228422 | controller | ok
2025-11-22 00:23:37.241085 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-22 00:23:37.260417 | 
2025-11-22 00:23:37.260571 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-22 00:23:37.287935 | controller | skipping: Conditional result was False
2025-11-22 00:23:37.301072 | 
2025-11-22 00:23:37.301230 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-22 00:23:37.571030 | controller | changed
2025-11-22 00:23:37.576885 | 
2025-11-22 00:23:37.576954 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-22 00:23:37.781482 | controller | ok
2025-11-22 00:23:37.789220 | 
2025-11-22 00:23:37.789315 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-22 00:23:38.430993 | controller | changed
2025-11-22 00:23:38.438735 | 
2025-11-22 00:23:38.438813 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-22 00:23:39.088162 | controller | changed
2025-11-22 00:23:39.100540 | 
2025-11-22 00:23:39.100640 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-22 00:23:39.126895 | controller | skipping: Conditional result was False
2025-11-22 00:23:39.135552 | 
2025-11-22 00:23:39.135642 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-22 00:23:39.425119 | controller -> localhost | changed
2025-11-22 00:23:39.492326 | 
2025-11-22 00:23:39.492497 | TASK [add-build-sshkey : Add back temp key]
2025-11-22 00:23:39.783323 | controller -> localhost | Identity added: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/1d0f30ceb6734442bf4d12455afd6b1e_id_ecdsa (zuul-build-sshkey)
2025-11-22 00:23:39.783768 | controller -> localhost | ok: Runtime: 0:00:00.012949
2025-11-22 00:23:39.797788 | 
2025-11-22 00:23:39.797929 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-22 00:23:40.006581 | controller | ok
2025-11-22 00:23:40.014702 | 
2025-11-22 00:23:40.014932 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-22 00:23:40.052876 | controller | skipping: Conditional result was False
2025-11-22 00:23:40.069121 | 
2025-11-22 00:23:40.069366 | TASK [include_role : remove-zuul-sshkey]
2025-11-22 00:23:40.089587 | controller | skipping: Conditional result was False
2025-11-22 00:23:40.104275 | 
2025-11-22 00:23:40.104516 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-22 00:23:40.333921 | controller | ok: "logs"
2025-11-22 00:23:40.334304 | controller | ok: All items complete
2025-11-22 00:23:40.334362 | 
2025-11-22 00:23:40.540265 | controller | ok: "artifacts"
2025-11-22 00:23:40.754494 | controller | ok: "docs"
2025-11-22 00:23:40.771896 | 
2025-11-22 00:23:40.772037 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-22 00:23:41.038921 | controller | changed: "logs"
2025-11-22 00:23:41.244380 | controller | changed: "artifacts"
2025-11-22 00:23:41.434375 | controller | changed: "docs"
2025-11-22 00:23:41.493344 | 
2025-11-22 00:23:41.493470 | PLAY RECAP
2025-11-22 00:23:41.493534 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-22 00:23:41.493570 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-22 00:23:41.493594 | 
2025-11-22 00:23:41.611574 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-22 00:23:41.612466 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-22 00:23:42.282901 | 
2025-11-22 00:23:42.283085 | PLAY [all]
2025-11-22 00:23:42.307110 | 
2025-11-22 00:23:42.307278 | TASK [Install binary dependencies]
2025-11-22 00:23:42.395072 | controller | ok
2025-11-22 00:23:42.429740 | 
2025-11-22 00:23:42.429920 | TASK [bindep : Include find tasks]
2025-11-22 00:23:42.466578 | controller | ok
2025-11-22 00:23:42.478703 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-22 00:23:42.488466 | 
2025-11-22 00:23:42.488563 | TASK [bindep : Look for bindep.txt]
2025-11-22 00:23:42.852806 | controller | ok
2025-11-22 00:23:42.861394 | 
2025-11-22 00:23:42.861494 | TASK [bindep : Define bindep_file fact]
2025-11-22 00:23:42.887323 | controller | skipping: Conditional result was False
2025-11-22 00:23:42.897348 | 
2025-11-22 00:23:42.897487 | TASK [bindep : Look for other-requirements.txt]
2025-11-22 00:23:43.119756 | controller | ok
2025-11-22 00:23:43.133297 | 
2025-11-22 00:23:43.133452 | TASK [bindep : Define bindep_file fact]
2025-11-22 00:23:43.176582 | controller | skipping: Conditional result was False
2025-11-22 00:23:43.191892 | 
2025-11-22 00:23:43.192163 | TASK [bindep : Look for bindep fallback file]
2025-11-22 00:23:43.232006 | controller | skipping: Conditional result was False
2025-11-22 00:23:43.244295 | 
2025-11-22 00:23:43.244515 | TASK [bindep : Define bindep_file fact]
2025-11-22 00:23:43.294341 | controller | skipping: Conditional result was False
2025-11-22 00:23:43.304128 | 
2025-11-22 00:23:43.304290 | TASK [bindep : Include bindep tasks]
2025-11-22 00:23:43.340511 | controller | skipping: Conditional result was False
2025-11-22 00:23:43.350822 | 
2025-11-22 00:23:43.350969 | TASK [bindep : Include install tasks]
2025-11-22 00:23:43.387992 | controller | skipping: Conditional result was False
2025-11-22 00:23:43.402124 | 
2025-11-22 00:23:43.402304 | LOOP [bindep : Include package tasks]
2025-11-22 00:23:43.487527 | 
2025-11-22 00:23:43.487783 | TASK [Run test-setup role]
2025-11-22 00:23:43.513798 | controller | ok
2025-11-22 00:23:43.538133 | 
2025-11-22 00:23:43.538241 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-22 00:23:43.756117 | controller | ok
2025-11-22 00:23:43.765131 | 
2025-11-22 00:23:43.765282 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-22 00:23:44.307413 | controller | skipping: Conditional result was False
2025-11-22 00:23:44.365970 | 
2025-11-22 00:23:44.366182 | PLAY RECAP
2025-11-22 00:23:44.366253 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-22 00:23:44.366284 | 
2025-11-22 00:23:44.505418 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-22 00:23:44.507824 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-22 00:23:45.186993 | 
2025-11-22 00:23:45.187190 | PLAY [controller]
2025-11-22 00:23:45.212715 | 
2025-11-22 00:23:45.212944 | TASK [Create the /root directory]
2025-11-22 00:23:45.624956 | controller | ok
2025-11-22 00:23:45.632954 | 
2025-11-22 00:23:45.633082 | TASK [Install glibc-langpack-en]
2025-11-22 00:23:49.663603 | controller | ok: Nothing to do
2025-11-22 00:23:49.676968 | 
2025-11-22 00:23:49.677139 | TASK [Ensure controller directory exists]
2025-11-22 00:23:49.906899 | controller | changed
2025-11-22 00:23:49.914347 | 
2025-11-22 00:23:49.914445 | TASK [Install container runtime]
2025-11-22 00:23:49.987875 | controller | ok
2025-11-22 00:23:50.028500 | 
2025-11-22 00:23:50.028708 | LOOP [ensure-podman : Find distribution installation]
2025-11-22 00:23:50.067897 | controller | ok: "/var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-22 00:23:50.075956 | controller | included: /var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-22 00:23:50.083038 | 
2025-11-22 00:23:50.083118 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-22 00:24:55.214076 | controller | changed
2025-11-22 00:24:55.230265 | 
2025-11-22 00:24:55.230445 | TASK [ensure-podman : Fetch podman version]
2025-11-22 00:24:55.797411 | controller | Client:       Podman Engine
2025-11-22 00:24:55.822991 | controller | Version:      4.6.2
2025-11-22 00:24:55.823017 | controller | API Version:  4.6.2
2025-11-22 00:24:55.823025 | controller | Go Version:   go1.19.12
2025-11-22 00:24:55.823042 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-22 00:24:55.823049 | controller | OS/Arch:      linux/amd64
2025-11-22 00:24:56.276304 | controller | ok: Runtime: 0:00:00.190458
2025-11-22 00:24:56.289284 | 
2025-11-22 00:24:56.289508 | TASK [ensure-podman : Print podman version installed]
2025-11-22 00:24:56.349261 | Podman version: Client:       Podman Engine
2025-11-22 00:24:56.349475 | Version:      4.6.2
2025-11-22 00:24:56.349503 | API Version:  4.6.2
2025-11-22 00:24:56.349523 | Go Version:   go1.19.12
2025-11-22 00:24:56.349542 | Built:        Mon Aug 28 19:38:31 2023
2025-11-22 00:24:56.349560 | OS/Arch:      linux/amd64
2025-11-22 00:24:56.355787 | 
2025-11-22 00:24:56.355875 | TASK [ensure-podman : Validate podman engine]
2025-11-22 00:24:56.896595 | controller | skipping: Conditional result was False
2025-11-22 00:24:56.913081 | 
2025-11-22 00:24:56.913251 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-22 00:24:56.951516 | controller | skipping: Conditional result was False
2025-11-22 00:24:56.963695 | 
2025-11-22 00:24:56.963788 | TASK [Ensure python3.8 is present]
2025-11-22 00:24:56.999144 | controller | skipping: Conditional result was False
2025-11-22 00:24:57.006786 | 
2025-11-22 00:24:57.006888 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-22 00:24:57.060987 | controller | ok
2025-11-22 00:24:57.084223 | 
2025-11-22 00:24:57.084359 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-22 00:24:58.481182 | controller | ok: Nothing to do
2025-11-22 00:24:58.493913 | 
2025-11-22 00:24:58.494049 | TASK [our-ensure-python : Also install python3-devel]
2025-11-22 00:25:08.201530 | controller | changed
2025-11-22 00:25:08.212586 | 
2025-11-22 00:25:08.212829 | TASK [Run ensure-virtualenv role]
2025-11-22 00:25:08.245939 | controller | ok
2025-11-22 00:25:08.268034 | 
2025-11-22 00:25:08.268188 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-22 00:25:08.541066 | controller | /usr/bin/virtualenv
2025-11-22 00:25:08.861851 | controller | ok: Runtime: 0:00:00.004981
2025-11-22 00:25:08.882057 | 
2025-11-22 00:25:08.882283 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-22 00:25:08.923596 | controller | skipping: Conditional result was False
2025-11-22 00:25:08.923954 | controller | ok: All items complete
2025-11-22 00:25:08.923999 | 
2025-11-22 00:25:08.951095 | 
2025-11-22 00:25:08.951261 | TASK [Find the full path of the Python interpreter]
2025-11-22 00:25:09.185897 | controller | /usr/bin/python3
2025-11-22 00:25:09.493858 | controller | ok
2025-11-22 00:25:09.503549 | 
2025-11-22 00:25:09.503729 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-22 00:25:10.347679 | controller | created virtual environment CPython3.11.0.final.0-64 in 511ms
2025-11-22 00:25:10.367228 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-22 00:25:10.367698 | 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-11-22 00:25:10.367887 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-22 00:25:10.368220 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-22 00:25:10.540888 | controller | changed
2025-11-22 00:25:10.554358 | 
2025-11-22 00:25:10.554507 | TASK [Set selinux package]
2025-11-22 00:25:10.594435 | controller | ok
2025-11-22 00:25:10.605900 | 
2025-11-22 00:25:10.606034 | TASK [Set selinux package (Fedora)]
2025-11-22 00:25:10.661505 | controller | ok
2025-11-22 00:25:10.668523 | 
2025-11-22 00:25:10.668608 | TASK [Install selinux into virtualenv]
2025-11-22 00:25:36.160638 | controller | Collecting selinux-please-lie-to-me
2025-11-22 00:25:48.389545 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-22 00:25:48.733485 | controller | Collecting setuptools<50.0.0
2025-11-22 00:25:48.784541 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-22 00:25:48.847969 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 13.9 MB/s eta 0:00:00
2025-11-22 00:25:48.931701 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-22 00:25:48.931898 | controller |   Attempting uninstall: setuptools
2025-11-22 00:25:48.934446 | controller |     Found existing installation: setuptools 62.6.0
2025-11-22 00:25:48.997217 | controller |     Uninstalling setuptools-62.6.0:
2025-11-22 00:25:49.005250 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-22 00:25:49.357585 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-22 00:26:00.751202 | controller |
2025-11-22 00:26:00.842661 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-22 00:26:00.842705 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-22 00:26:01.243127 | controller | ok: Runtime: 0:00:49.960121
2025-11-22 00:26:01.248965 | 
2025-11-22 00:26:01.249026 | TASK [Install pytest-forked into virtualenv]
2025-11-22 00:26:13.005860 | controller | Collecting pytest-forked
2025-11-22 00:26:23.196515 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-22 00:26:23.240219 | controller | Collecting py
2025-11-22 00:26:23.262160 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-22 00:26:23.283847 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.6 MB/s eta 0:00:00
2025-11-22 00:26:23.394634 | controller | Collecting pytest>=3.10
2025-11-22 00:26:23.404054 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-22 00:26:23.426427 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 18.6 MB/s eta 0:00:00
2025-11-22 00:26:23.468092 | controller | Collecting iniconfig>=1.0.1
2025-11-22 00:26:23.477037 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-22 00:26:23.519116 | controller | Collecting packaging>=22
2025-11-22 00:26:23.544182 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-22 00:26:23.552615 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 12.9 MB/s eta 0:00:00
2025-11-22 00:26:23.589566 | controller | Collecting pluggy<2,>=1.5
2025-11-22 00:26:23.595961 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-22 00:26:23.644340 | controller | Collecting pygments>=2.7.2
2025-11-22 00:26:23.653247 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-22 00:26:23.702788 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 26.7 MB/s eta 0:00:00
2025-11-22 00:26:23.772173 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-22 00:26:24.803288 | 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.1 pytest-forked-1.6.0
2025-11-22 00:26:24.811548 | controller |
2025-11-22 00:26:24.877869 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-22 00:26:24.877910 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-22 00:26:25.295432 | controller | ok: Runtime: 0:00:23.403145
2025-11-22 00:26:25.313249 | 
2025-11-22 00:26:25.313515 | TASK [Update pip]
2025-11-22 00:26:25.904299 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-22 00:26:38.330439 | controller | Collecting pip
2025-11-22 00:26:50.644555 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-22 00:26:50.706696 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.3 MB/s eta 0:00:00
2025-11-22 00:26:50.776399 | controller | Installing collected packages: pip
2025-11-22 00:26:50.776635 | controller |   Attempting uninstall: pip
2025-11-22 00:26:50.778832 | controller |     Found existing installation: pip 22.2.2
2025-11-22 00:26:50.918695 | controller |     Uninstalling pip-22.2.2:
2025-11-22 00:26:50.935085 | controller |       Successfully uninstalled pip-22.2.2
2025-11-22 00:26:51.725873 | controller | Successfully installed pip-25.3
2025-11-22 00:26:51.933923 | controller | ok: Runtime: 0:00:26.192877
2025-11-22 00:26:51.946891 | 
2025-11-22 00:26:51.947040 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-22 00:26:52.166522 | controller | changed
2025-11-22 00:26:52.174745 | 
2025-11-22 00:26:52.174847 | TASK [Install ansible into virtualenv]
2025-11-22 00:26:52.686148 | controller | Processing ./src/github.com/ansible/ansible
2025-11-22 00:26:52.689306 | controller |   Installing build dependencies: started
2025-11-22 00:27:15.798313 | controller |   Installing build dependencies: finished with status 'done'
2025-11-22 00:27:15.798983 | controller |   Getting requirements to build wheel: started
2025-11-22 00:27:16.514277 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-22 00:27:16.515767 | controller |   Preparing metadata (pyproject.toml): started
2025-11-22 00:27:16.994274 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-22 00:27:16.997845 | 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-11-22 00:27:17.001681 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-22 00:27:17.229455 | controller | ERROR
2025-11-22 00:27:17.229789 | controller | {
2025-11-22 00:27:17.229858 | controller |   "delta": "0:00:24.658339",
2025-11-22 00:27:17.229901 | controller |   "end": "2025-11-22 00:27:17.066251",
2025-11-22 00:27:17.229941 | controller |   "msg": "non-zero return code",
2025-11-22 00:27:17.230007 | controller |   "rc": 1,
2025-11-22 00:27:17.230045 | controller |   "start": "2025-11-22 00:26:52.407912"
2025-11-22 00:27:17.230079 | controller | }
failure
2025-11-22 00:27:17.232371 | 
2025-11-22 00:27:17.232554 | PLAY RECAP
2025-11-22 00:27:17.232807 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-22 00:27:17.232857 | 
2025-11-22 00:27:17.362724 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-22 00:27:17.364184 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-22 00:27:17.919865 | 
2025-11-22 00:27:17.919974 | PLAY [all]
2025-11-22 00:27:17.940921 | 
2025-11-22 00:27:17.941003 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-22 00:27:18.203394 | controller | changed: non-zero return code
2025-11-22 00:27:18.216730 | 
2025-11-22 00:27:18.216891 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-22 00:27:18.244749 | controller | skipping: Conditional result was False
2025-11-22 00:27:18.257538 | 
2025-11-22 00:27:18.257730 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-22 00:27:18.299125 | 
2025-11-22 00:27:18.299363 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-22 00:27:18.340546 | 
2025-11-22 00:27:18.340862 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-22 00:27:18.368856 | controller | skipping: Conditional result was False
2025-11-22 00:27:18.385301 | 
2025-11-22 00:27:18.385476 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-22 00:27:18.425465 | 
2025-11-22 00:27:18.425749 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-22 00:27:18.452817 | controller | skipping: Conditional result was False
2025-11-22 00:27:18.465516 | 
2025-11-22 00:27:18.465651 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-22 00:27:18.493287 | controller | skipping: Conditional result was False
2025-11-22 00:27:18.506317 | 
2025-11-22 00:27:18.506462 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-22 00:27:18.534178 | controller | skipping: Conditional result was False
2025-11-22 00:27:18.587364 | 
2025-11-22 00:27:18.587581 | PLAY RECAP
2025-11-22 00:27:18.587645 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-22 00:27:18.587743 | 
2025-11-22 00:27:18.694474 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-22 00:27:18.695339 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-22 00:27:19.314042 | 
2025-11-22 00:27:19.314165 | PLAY [all:!appliance*]
2025-11-22 00:27:19.336923 | 
2025-11-22 00:27:19.337073 | TASK [unregister the node]
2025-11-22 00:27:19.869075 | controller | skipping: Conditional result was False
2025-11-22 00:27:19.883391 | 
2025-11-22 00:27:19.883579 | TASK [include_role : fetch-output]
2025-11-22 00:27:19.935477 | controller | ok
2025-11-22 00:27:19.975992 | 
2025-11-22 00:27:19.976150 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-22 00:27:20.053166 | controller | skipping: Conditional result was False
2025-11-22 00:27:20.066654 | 
2025-11-22 00:27:20.066837 | TASK [fetch-output : Set log path for single node]
2025-11-22 00:27:20.122485 | controller | ok
2025-11-22 00:27:20.131210 | 
2025-11-22 00:27:20.131367 | LOOP [fetch-output : Ensure local output dirs]
2025-11-22 00:27:20.574429 | controller -> localhost | ok: "/var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/logs"
2025-11-22 00:27:20.858470 | controller -> localhost | changed: "/var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/artifacts"
2025-11-22 00:27:21.131759 | controller -> localhost | changed: "/var/lib/zuul/builds/1d0f30ceb6734442bf4d12455afd6b1e/work/docs"
2025-11-22 00:27:21.158994 | 
2025-11-22 00:27:21.159186 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-22 00:27:21.865243 | controller | changed:
2025-11-22 00:27:21.865597 | controller | .d..t...... ./
2025-11-22 00:27:21.865704 | controller | cd+++++++++ controller/
2025-11-22 00:27:21.865816 | controller | changed: All items complete
2025-11-22 00:27:21.865868 | 
2025-11-22 00:27:22.342285 | controller | changed: .d..t...... ./
2025-11-22 00:27:22.852551 | controller | changed: .d..t...... ./
2025-11-22 00:27:22.870162 | 
2025-11-22 00:27:22.870266 | TASK [include_role : fetch-output-openshift]
2025-11-22 00:27:22.894983 | controller | skipping: Conditional result was False
2025-11-22 00:27:22.908827 | 
2025-11-22 00:27:22.908966 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-22 00:27:22.934272 | controller | skipping: Conditional result was False
2025-11-22 00:27:22.942792 | controller | skipping: Conditional result was False
2025-11-22 00:27:22.983835 | 
2025-11-22 00:27:22.983948 | PLAY [localhost]
2025-11-22 00:27:23.001086 | 
2025-11-22 00:27:23.001175 | TASK [Run Zuul manifest role]
2025-11-22 00:27:23.021120 | localhost | ok
2025-11-22 00:27:23.040863 | 
2025-11-22 00:27:23.040970 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-22 00:27:23.436598 | localhost | changed
2025-11-22 00:27:23.441606 | 
2025-11-22 00:27:23.441690 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-22 00:27:23.468957 | localhost | ok
2025-11-22 00:27:23.477454 | 
2025-11-22 00:27:23.477556 | TASK [Set zuul-log-path fact]
2025-11-22 00:27:23.495995 | localhost | ok
2025-11-22 00:27:23.509746 | 
2025-11-22 00:27:23.509973 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-22 00:27:23.547465 | localhost | ok
2025-11-22 00:27:23.555595 | 
2025-11-22 00:27:23.555658 | LOOP [Run upload-logs-swift role]
2025-11-22 00:27:23.579280 | localhost | Output suppressed because no_log was given
2025-11-22 00:27:23.604349 | 
2025-11-22 00:27:23.604455 | TASK [Set zuul-log-path fact]
2025-11-22 00:27:23.627857 | localhost | skipping: Conditional result was False
2025-11-22 00:27:23.633311 | 
2025-11-22 00:27:23.633394 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-22 00:27:24.044980 | localhost -> localhost | ok: Runtime: 0:00:00.004921
2025-11-22 00:27:24.091562 | 
2025-11-22 00:27:24.091720 | TASK [upload-logs-swift : Upload logs to swift]