2026-01-27 00:22:53.284757 | Job console starting...
2026-01-27 00:22:53.297168 | Updating repositories
2026-01-27 00:22:53.417547 | Preparing job workspace
2026-01-27 00:22:57.581113 | Running Ansible setup...
2026-01-27 00:23:02.356287 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-27 00:23:04.461474 | 
2026-01-27 00:23:04.461612 | PLAY [localhost]
2026-01-27 00:23:04.470719 | 
2026-01-27 00:23:04.470811 | TASK [Gathering Facts]
2026-01-27 00:23:05.458341 | localhost | ok
2026-01-27 00:23:05.474346 | 
2026-01-27 00:23:05.474484 | TASK [Setup log path fact]
2026-01-27 00:23:05.492178 | localhost | ok
2026-01-27 00:23:05.506509 | 
2026-01-27 00:23:05.506641 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-27 00:23:05.535149 | localhost | ok
2026-01-27 00:23:05.544133 | 
2026-01-27 00:23:05.544269 | TASK [emit-job-header : Print job information]
2026-01-27 00:23:05.573392 | # Job Information
2026-01-27 00:23:05.573588 | Ansible Version: 2.15.12
2026-01-27 00:23:05.573621 | Job: ansible-test-sanity-docker-devel
2026-01-27 00:23:05.573642 | Pipeline: periodic
2026-01-27 00:23:05.573660 | Executor: ze04.softwarefactory-project.io
2026-01-27 00:23:05.573703 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-27 00:23:05.573731 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/a67/ansible/a6799d7b0f5d427f9718b7c1018e84e1/
2026-01-27 00:23:05.573751 | Event ID: 09a8597d6a8b4d889213d53e421fb5a7
2026-01-27 00:23:05.577421 | 
2026-01-27 00:23:05.577482 | LOOP [emit-job-header : Print node information]
2026-01-27 00:23:05.678466 | localhost | ok:
2026-01-27 00:23:05.678668 | localhost | # Node Information
2026-01-27 00:23:05.678723 | localhost | Inventory Hostname: controller
2026-01-27 00:23:05.678748 | localhost | Hostname: np0005596705
2026-01-27 00:23:05.678772 | localhost | Username: zuul
2026-01-27 00:23:05.678799 | localhost | Distro: Fedora 37
2026-01-27 00:23:05.678821 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2026-01-27 00:23:05.678842 | localhost | Region: ca-ymq-1
2026-01-27 00:23:05.678862 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-27 00:23:05.678882 | localhost | Product Name: OpenStack Nova
2026-01-27 00:23:05.678903 | localhost | Interface IP: 162.253.55.70
2026-01-27 00:23:05.691134 | 
2026-01-27 00:23:05.691272 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-27 00:23:06.083697 | localhost -> localhost | changed
2026-01-27 00:23:06.092899 | 
2026-01-27 00:23:06.093016 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-27 00:23:07.031110 | localhost -> localhost | changed
2026-01-27 00:23:07.063213 | 
2026-01-27 00:23:07.063336 | PLAY [all:!appliance*]
2026-01-27 00:23:07.081979 | 
2026-01-27 00:23:07.082065 | TASK [include_role : start-zuul-console]
2026-01-27 00:23:07.106204 | controller | ok
2026-01-27 00:23:07.126947 | 
2026-01-27 00:23:07.127075 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-27 00:23:07.506597 | controller | ok
2026-01-27 00:23:07.522074 | 
2026-01-27 00:23:07.522182 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-27 00:23:08.603479 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-27 00:23:08.621734 | 
2026-01-27 00:23:08.621949 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-27 00:23:09.172113 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.183062 | 
2026-01-27 00:23:09.183228 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-27 00:23:09.198837 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.209213 | 
2026-01-27 00:23:09.209349 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-27 00:23:09.244543 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.254984 | 
2026-01-27 00:23:09.255151 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-27 00:23:09.290827 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.300131 | 
2026-01-27 00:23:09.300303 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-27 00:23:09.326371 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.339372 | 
2026-01-27 00:23:09.339564 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-27 00:23:09.375531 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.393721 | 
2026-01-27 00:23:09.393851 | TASK [Disable Fedora Modular]
2026-01-27 00:23:09.652310 | controller | changed
2026-01-27 00:23:09.661338 | 
2026-01-27 00:23:09.661659 | TASK [Enable EPEL]
2026-01-27 00:23:09.700493 | controller | skipping: Conditional result was False
2026-01-27 00:23:09.710805 | 
2026-01-27 00:23:09.710940 | TASK [Register the RHEL node]
2026-01-27 00:23:10.295004 | 
2026-01-27 00:23:10.295424 | TASK [Show the subscription-manager status]
2026-01-27 00:23:10.893363 | controller | skipping: Conditional result was False
2026-01-27 00:23:10.903818 | 
2026-01-27 00:23:10.903957 | TASK [Enable EPEL on RHEL]
2026-01-27 00:23:11.442407 | controller | skipping: Conditional result was False
2026-01-27 00:23:11.456351 | 
2026-01-27 00:23:11.456521 | TASK [Install git and tox]
2026-01-27 00:24:33.193165 | controller | changed
2026-01-27 00:24:33.203864 | 
2026-01-27 00:24:33.203976 | TASK [include_role : prepare-workspace]
2026-01-27 00:24:33.240103 | controller | ok
2026-01-27 00:24:33.273602 | 
2026-01-27 00:24:33.273785 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-27 00:24:33.502217 | controller | ok
2026-01-27 00:24:33.509626 | 
2026-01-27 00:24:33.509740 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-27 00:24:45.720776 | controller | Output suppressed because no_log was given
2026-01-27 00:24:45.735940 | 
2026-01-27 00:24:45.736068 | TASK [include_role : prepare-workspace-openshift]
2026-01-27 00:24:45.761974 | controller | skipping: Conditional result was False
2026-01-27 00:24:45.839427 | 
2026-01-27 00:24:45.839531 | PLAY [all:!appliance]
2026-01-27 00:24:45.864020 | 
2026-01-27 00:24:45.864185 | TASK [Run add-build-sshkey role (RSA)]
2026-01-27 00:24:45.897444 | controller | ok
2026-01-27 00:24:45.922436 | 
2026-01-27 00:24:45.922547 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-27 00:24:46.203219 | controller -> localhost | ok
2026-01-27 00:24:46.222929 | 
2026-01-27 00:24:46.223106 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-27 00:24:46.263448 | controller | ok
2026-01-27 00:24:46.290764 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-27 00:24:46.300236 | 
2026-01-27 00:24:46.300536 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-27 00:24:46.857840 | controller -> localhost | Generating public/private rsa key pair.
2026-01-27 00:24:46.858214 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_rsa.
2026-01-27 00:24:46.858281 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_rsa.pub.
2026-01-27 00:24:46.858329 | controller -> localhost | The key fingerprint is:
2026-01-27 00:24:46.858373 | controller -> localhost | SHA256:pC0STZnrRbKPu4pSAcZn098lPcEEsEBUbktNcAT3xnI zuul-build-sshkey
2026-01-27 00:24:46.858418 | controller -> localhost | The key's randomart image is:
2026-01-27 00:24:46.858478 | controller -> localhost | +---[RSA 2048]----+
2026-01-27 00:24:46.858824 | controller -> localhost | |.   ++oB=*=o.    |
2026-01-27 00:24:46.858880 | controller -> localhost | |.o + +* B.o=     |
2026-01-27 00:24:46.858926 | controller -> localhost | |..o o oXoooE.    |
2026-01-27 00:24:46.858966 | controller -> localhost | |  .  .==o.+      |
2026-01-27 00:24:46.859002 | controller -> localhost | |   ...o=S        |
2026-01-27 00:24:46.859060 | controller -> localhost | |  .  .o..        |
2026-01-27 00:24:46.859107 | controller -> localhost | | .     .         |
2026-01-27 00:24:46.859150 | controller -> localhost | |.  .  .          |
2026-01-27 00:24:46.859189 | controller -> localhost | | .. ....         |
2026-01-27 00:24:46.859234 | controller -> localhost | +----[SHA256]-----+
2026-01-27 00:24:46.859331 | controller -> localhost | ok: Runtime: 0:00:00.065206
2026-01-27 00:24:46.873773 | 
2026-01-27 00:24:46.873910 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-27 00:24:46.915864 | controller | ok
2026-01-27 00:24:46.939855 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-27 00:24:46.961970 | 
2026-01-27 00:24:46.962126 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-27 00:24:46.998649 | controller | skipping: Conditional result was False
2026-01-27 00:24:47.011631 | 
2026-01-27 00:24:47.011858 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-27 00:24:47.462634 | controller | changed
2026-01-27 00:24:47.476862 | 
2026-01-27 00:24:47.477052 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-27 00:24:47.708345 | controller | ok
2026-01-27 00:24:47.717254 | 
2026-01-27 00:24:47.717399 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-27 00:24:48.375375 | controller | changed
2026-01-27 00:24:48.390036 | 
2026-01-27 00:24:48.390235 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-27 00:24:49.040056 | controller | changed
2026-01-27 00:24:49.056429 | 
2026-01-27 00:24:49.056651 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-27 00:24:49.085219 | controller | skipping: Conditional result was False
2026-01-27 00:24:49.097222 | 
2026-01-27 00:24:49.097356 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-27 00:24:49.502875 | controller -> localhost | changed
2026-01-27 00:24:49.517516 | 
2026-01-27 00:24:49.517715 | TASK [add-build-sshkey : Add back temp key]
2026-01-27 00:24:49.834750 | controller -> localhost | Identity added: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_rsa (zuul-build-sshkey)
2026-01-27 00:24:49.835058 | controller -> localhost | ok: Runtime: 0:00:00.017674
2026-01-27 00:24:49.841896 | 
2026-01-27 00:24:49.842033 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-27 00:24:50.202356 | controller | ok
2026-01-27 00:24:50.208175 | 
2026-01-27 00:24:50.208246 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-27 00:24:50.233273 | controller | skipping: Conditional result was False
2026-01-27 00:24:50.245030 | 
2026-01-27 00:24:50.245125 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-27 00:24:50.265318 | controller | ok
2026-01-27 00:24:50.282398 | 
2026-01-27 00:24:50.282523 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-27 00:24:50.522561 | controller -> localhost | ok
2026-01-27 00:24:50.529831 | 
2026-01-27 00:24:50.529939 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-27 00:24:50.551174 | controller | ok
2026-01-27 00:24:50.565728 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-27 00:24:50.572341 | 
2026-01-27 00:24:50.572410 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-27 00:24:50.892736 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-27 00:24:50.892967 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_ecdsa.
2026-01-27 00:24:50.893010 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_ecdsa.pub.
2026-01-27 00:24:50.893059 | controller -> localhost | The key fingerprint is:
2026-01-27 00:24:50.893093 | controller -> localhost | SHA256:kJv6onXvTiFzzOE0sURIKApXURAl2JAxq8HppqXP4uU zuul-build-sshkey
2026-01-27 00:24:50.893123 | controller -> localhost | The key's randomart image is:
2026-01-27 00:24:50.893153 | controller -> localhost | +---[ECDSA 521]---+
2026-01-27 00:24:50.893181 | controller -> localhost | |  +B*O+o+        |
2026-01-27 00:24:50.893210 | controller -> localhost | |o *oo..o o       |
2026-01-27 00:24:50.893238 | controller -> localhost | |o=..  o =        |
2026-01-27 00:24:50.893269 | controller -> localhost | |oo     O o       |
2026-01-27 00:24:50.893298 | controller -> localhost | |.o.   = S        |
2026-01-27 00:24:50.893326 | controller -> localhost | |oo   . + .       |
2026-01-27 00:24:50.893359 | controller -> localhost | |o  .o . .        |
2026-01-27 00:24:50.893398 | controller -> localhost | |.oo..o o         |
2026-01-27 00:24:50.893436 | controller -> localhost | |.o+E ..o+        |
2026-01-27 00:24:50.893477 | controller -> localhost | +----[SHA256]-----+
2026-01-27 00:24:50.893571 | controller -> localhost | ok: Runtime: 0:00:00.007872
2026-01-27 00:24:50.908310 | 
2026-01-27 00:24:50.908461 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-27 00:24:50.933869 | controller | ok
2026-01-27 00:24:50.945607 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-27 00:24:50.958188 | 
2026-01-27 00:24:50.958273 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-27 00:24:50.982924 | controller | skipping: Conditional result was False
2026-01-27 00:24:50.989423 | 
2026-01-27 00:24:50.989507 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-27 00:24:51.251100 | controller | changed
2026-01-27 00:24:51.268660 | 
2026-01-27 00:24:51.268918 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-27 00:24:51.504661 | controller | ok
2026-01-27 00:24:51.518326 | 
2026-01-27 00:24:51.518484 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-27 00:24:52.151584 | controller | changed
2026-01-27 00:24:52.161344 | 
2026-01-27 00:24:52.161507 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-27 00:24:52.756826 | controller | changed
2026-01-27 00:24:52.765342 | 
2026-01-27 00:24:52.765477 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-27 00:24:52.791384 | controller | skipping: Conditional result was False
2026-01-27 00:24:52.805230 | 
2026-01-27 00:24:52.805416 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-27 00:24:53.069423 | controller -> localhost | changed
2026-01-27 00:24:53.084213 | 
2026-01-27 00:24:53.084316 | TASK [add-build-sshkey : Add back temp key]
2026-01-27 00:24:53.463348 | controller -> localhost | Identity added: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/a6799d7b0f5d427f9718b7c1018e84e1_id_ecdsa (zuul-build-sshkey)
2026-01-27 00:24:53.463606 | controller -> localhost | ok: Runtime: 0:00:00.008880
2026-01-27 00:24:53.511340 | 
2026-01-27 00:24:53.511474 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-27 00:24:53.708583 | controller | ok
2026-01-27 00:24:53.718193 | 
2026-01-27 00:24:53.718322 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-27 00:24:53.745517 | controller | skipping: Conditional result was False
2026-01-27 00:24:53.766268 | 
2026-01-27 00:24:53.766472 | TASK [include_role : remove-zuul-sshkey]
2026-01-27 00:24:53.796029 | controller | skipping: Conditional result was False
2026-01-27 00:24:53.807244 | 
2026-01-27 00:24:53.807350 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-27 00:24:54.051462 | controller | ok: "logs"
2026-01-27 00:24:54.051950 | controller | ok: All items complete
2026-01-27 00:24:54.052009 | 
2026-01-27 00:24:54.241275 | controller | ok: "artifacts"
2026-01-27 00:29:59.842134 | controller | ok: "docs"
2026-01-27 00:29:59.860813 | 
2026-01-27 00:29:59.860938 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-27 00:30:00.082895 | controller | changed: "logs"
2026-01-27 00:30:00.267762 | controller | changed: "artifacts"
2026-01-27 00:30:00.453236 | controller | changed: "docs"
2026-01-27 00:30:00.490911 | 
2026-01-27 00:30:00.491045 | PLAY RECAP
2026-01-27 00:30:00.491221 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-27 00:30:00.491845 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-27 00:30:00.491878 | 
2026-01-27 00:30:00.656957 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-27 00:30:00.658219 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-27 00:30:01.423515 | 
2026-01-27 00:30:01.423715 | PLAY [all]
2026-01-27 00:30:01.449655 | 
2026-01-27 00:30:01.449828 | TASK [Install binary dependencies]
2026-01-27 00:30:01.513133 | controller | ok
2026-01-27 00:30:01.535272 | 
2026-01-27 00:30:01.535421 | TASK [bindep : Include find tasks]
2026-01-27 00:30:01.571177 | controller | ok
2026-01-27 00:30:01.587508 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-27 00:30:01.600496 | 
2026-01-27 00:30:01.600893 | TASK [bindep : Look for bindep.txt]
2026-01-27 00:30:02.161059 | controller | ok
2026-01-27 00:30:02.175493 | 
2026-01-27 00:30:02.175658 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:30:02.202990 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.211190 | 
2026-01-27 00:30:02.211276 | TASK [bindep : Look for other-requirements.txt]
2026-01-27 00:30:02.409765 | controller | ok
2026-01-27 00:30:02.419310 | 
2026-01-27 00:30:02.419439 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:30:02.446666 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.455557 | 
2026-01-27 00:30:02.455707 | TASK [bindep : Look for bindep fallback file]
2026-01-27 00:30:02.482218 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.492362 | 
2026-01-27 00:30:02.492493 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:30:02.519666 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.531420 | 
2026-01-27 00:30:02.531563 | TASK [bindep : Include bindep tasks]
2026-01-27 00:30:02.560169 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.570517 | 
2026-01-27 00:30:02.570643 | TASK [bindep : Include install tasks]
2026-01-27 00:30:02.606420 | controller | skipping: Conditional result was False
2026-01-27 00:30:02.615122 | 
2026-01-27 00:30:02.615232 | LOOP [bindep : Include package tasks]
2026-01-27 00:30:02.697371 | 
2026-01-27 00:30:02.697589 | TASK [Run test-setup role]
2026-01-27 00:30:02.729827 | controller | ok
2026-01-27 00:30:02.761912 | 
2026-01-27 00:30:02.762070 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-27 00:30:02.972157 | controller | ok
2026-01-27 00:30:02.981630 | 
2026-01-27 00:30:02.981799 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-27 00:30:03.527357 | controller | skipping: Conditional result was False
2026-01-27 00:30:03.581325 | 
2026-01-27 00:30:03.581472 | PLAY RECAP
2026-01-27 00:30:03.581610 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-27 00:30:03.581644 | 
2026-01-27 00:30:03.732222 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-27 00:30:03.733171 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-27 00:30:04.356045 | 
2026-01-27 00:30:04.356204 | PLAY [controller]
2026-01-27 00:30:04.379980 | 
2026-01-27 00:30:04.380114 | TASK [Create the /root directory]
2026-01-27 00:30:04.946596 | controller | ok
2026-01-27 00:30:04.953478 | 
2026-01-27 00:30:04.953582 | TASK [Install glibc-langpack-en]
2026-01-27 00:30:08.743395 | controller | ok: Nothing to do
2026-01-27 00:30:08.748986 | 
2026-01-27 00:30:08.749055 | TASK [Ensure controller directory exists]
2026-01-27 00:30:08.946124 | controller | changed
2026-01-27 00:30:08.955709 | 
2026-01-27 00:30:08.955801 | TASK [Install container runtime]
2026-01-27 00:30:08.995410 | controller | ok
2026-01-27 00:30:09.028878 | 
2026-01-27 00:30:09.028982 | LOOP [ensure-podman : Find distribution installation]
2026-01-27 00:30:09.050935 | controller | ok: "/var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-27 00:30:09.059550 | controller | included: /var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-27 00:30:09.070409 | 
2026-01-27 00:30:09.070529 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-27 00:31:15.113486 | controller | changed
2026-01-27 00:31:15.122497 | 
2026-01-27 00:31:15.122598 | TASK [ensure-podman : Fetch podman version]
2026-01-27 00:31:15.609309 | controller | Client:       Podman Engine
2026-01-27 00:31:15.609397 | controller | Version:      4.6.2
2026-01-27 00:31:15.609430 | controller | API Version:  4.6.2
2026-01-27 00:31:15.609460 | controller | Go Version:   go1.19.12
2026-01-27 00:31:15.609499 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-27 00:31:15.609531 | controller | OS/Arch:      linux/amd64
2026-01-27 00:31:15.664804 | controller | ok: Runtime: 0:00:00.176380
2026-01-27 00:31:15.671318 | 
2026-01-27 00:31:15.671418 | TASK [ensure-podman : Print podman version installed]
2026-01-27 00:31:15.701664 | Podman version: Client:       Podman Engine
2026-01-27 00:31:15.701836 | Version:      4.6.2
2026-01-27 00:31:15.701873 | API Version:  4.6.2
2026-01-27 00:31:15.701896 | Go Version:   go1.19.12
2026-01-27 00:31:15.701917 | Built:        Mon Aug 28 19:38:31 2023
2026-01-27 00:31:15.701943 | OS/Arch:      linux/amd64
2026-01-27 00:31:15.708031 | 
2026-01-27 00:31:15.708103 | TASK [ensure-podman : Validate podman engine]
2026-01-27 00:31:16.240745 | controller | skipping: Conditional result was False
2026-01-27 00:31:16.250517 | 
2026-01-27 00:31:16.250667 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-27 00:31:16.266142 | controller | skipping: Conditional result was False
2026-01-27 00:31:16.285969 | 
2026-01-27 00:31:16.286116 | TASK [Ensure python3.8 is present]
2026-01-27 00:31:16.301646 | controller | skipping: Conditional result was False
2026-01-27 00:31:16.311347 | 
2026-01-27 00:31:16.311483 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-27 00:31:16.338463 | controller | ok
2026-01-27 00:31:16.365990 | 
2026-01-27 00:31:16.366113 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-27 00:31:17.786503 | controller | ok: Nothing to do
2026-01-27 00:31:17.792234 | 
2026-01-27 00:31:17.792301 | TASK [our-ensure-python : Also install python3-devel]
2026-01-27 00:31:26.407001 | controller | changed
2026-01-27 00:31:26.437524 | 
2026-01-27 00:31:26.437750 | TASK [Run ensure-virtualenv role]
2026-01-27 00:31:26.463960 | controller | ok
2026-01-27 00:31:26.495641 | 
2026-01-27 00:31:26.495818 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-27 00:31:26.728553 | controller | /usr/bin/virtualenv
2026-01-27 00:31:27.055308 | controller | ok: Runtime: 0:00:00.003279
2026-01-27 00:31:27.067818 | 
2026-01-27 00:31:27.067969 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-27 00:31:27.098585 | controller | skipping: Conditional result was False
2026-01-27 00:31:27.099199 | controller | ok: All items complete
2026-01-27 00:31:27.099261 | 
2026-01-27 00:31:27.115578 | 
2026-01-27 00:31:27.115718 | TASK [Find the full path of the Python interpreter]
2026-01-27 00:31:27.323335 | controller | /usr/bin/python3
2026-01-27 00:31:27.651662 | controller | ok
2026-01-27 00:31:27.669302 | 
2026-01-27 00:31:27.669554 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-27 00:31:28.450328 | controller | created virtual environment CPython3.11.0.final.0-64 in 432ms
2026-01-27 00:31:28.480193 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-27 00:31:28.480234 | 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)
2026-01-27 00:31:28.480245 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-27 00:31:28.480261 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-27 00:31:28.729812 | controller | changed
2026-01-27 00:31:28.746734 | 
2026-01-27 00:31:28.746947 | TASK [Set selinux package]
2026-01-27 00:31:28.788048 | controller | ok
2026-01-27 00:31:28.799156 | 
2026-01-27 00:31:28.799313 | TASK [Set selinux package (Fedora)]
2026-01-27 00:31:28.852758 | controller | ok
2026-01-27 00:31:28.860391 | 
2026-01-27 00:31:28.860524 | TASK [Install selinux into virtualenv]
2026-01-27 00:31:30.125482 | controller | Collecting selinux-please-lie-to-me
2026-01-27 00:31:30.177198 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-27 00:31:30.512706 | controller | Collecting setuptools<50.0.0
2026-01-27 00:31:30.516777 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-27 00:31:30.552369 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 25.4 MB/s eta 0:00:00
2026-01-27 00:31:30.632090 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-27 00:31:30.632359 | controller |   Attempting uninstall: setuptools
2026-01-27 00:31:30.634717 | controller |     Found existing installation: setuptools 62.6.0
2026-01-27 00:31:30.695096 | controller |     Uninstalling setuptools-62.6.0:
2026-01-27 00:31:30.703188 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-27 00:31:31.049763 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-27 00:31:31.178700 | controller |
2026-01-27 00:31:31.275718 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-27 00:31:31.275759 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-27 00:31:31.411069 | controller | ok: Runtime: 0:00:02.198926
2026-01-27 00:31:31.420156 | 
2026-01-27 00:31:31.420342 | TASK [Install pytest-forked into virtualenv]
2026-01-27 00:31:32.027632 | controller | Collecting pytest-forked
2026-01-27 00:31:32.061700 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-27 00:31:32.098532 | controller | Collecting py
2026-01-27 00:31:32.105746 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-27 00:31:32.124023 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.6 MB/s eta 0:00:00
2026-01-27 00:31:32.226436 | controller | Collecting pytest>=3.10
2026-01-27 00:31:32.233752 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-27 00:31:32.246417 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 38.4 MB/s eta 0:00:00
2026-01-27 00:31:32.276610 | controller | Collecting iniconfig>=1.0.1
2026-01-27 00:31:32.281543 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-27 00:31:32.320294 | controller | Collecting packaging>=22
2026-01-27 00:31:32.323294 | controller |   Downloading packaging-26.0-py3-none-any.whl (74 kB)
2026-01-27 00:31:32.330063 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 74.4/74.4 kB 12.9 MB/s eta 0:00:00
2026-01-27 00:31:32.356369 | controller | Collecting pluggy<2,>=1.5
2026-01-27 00:31:32.360854 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-27 00:31:32.404010 | controller | Collecting pygments>=2.7.2
2026-01-27 00:31:32.406935 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-27 00:31:32.433593 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 62.4 MB/s eta 0:00:00
2026-01-27 00:31:32.498251 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-27 00:31:33.592283 | controller | Successfully installed iniconfig-2.3.0 packaging-26.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2026-01-27 00:31:33.600617 | controller |
2026-01-27 00:31:33.664446 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-27 00:31:33.664488 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-27 00:31:33.967811 | controller | ok: Runtime: 0:00:02.013256
2026-01-27 00:31:33.980386 | 
2026-01-27 00:31:33.980521 | TASK [Update pip]
2026-01-27 00:31:34.500813 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-27 00:31:34.621806 | controller | Collecting pip
2026-01-27 00:31:34.653844 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-27 00:31:34.696882 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 43.7 MB/s eta 0:00:00
2026-01-27 00:31:34.759456 | controller | Installing collected packages: pip
2026-01-27 00:31:34.759677 | controller |   Attempting uninstall: pip
2026-01-27 00:31:34.761851 | controller |     Found existing installation: pip 22.2.2
2026-01-27 00:31:34.898299 | controller |     Uninstalling pip-22.2.2:
2026-01-27 00:31:34.913115 | controller |       Successfully uninstalled pip-22.2.2
2026-01-27 00:31:35.770850 | controller | Successfully installed pip-25.3
2026-01-27 00:31:36.055823 | controller | ok: Runtime: 0:00:01.628101
2026-01-27 00:31:36.070257 | 
2026-01-27 00:31:36.070454 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-27 00:31:36.278083 | controller | changed
2026-01-27 00:31:36.284193 | 
2026-01-27 00:31:36.284292 | TASK [Install ansible into virtualenv]
2026-01-27 00:31:36.753988 | controller | Processing ./src/github.com/ansible/ansible
2026-01-27 00:31:36.757346 | controller |   Installing build dependencies: started
2026-01-27 00:31:38.009208 | controller |   Installing build dependencies: finished with status 'done'
2026-01-27 00:31:38.726108 | controller |   Getting requirements to build wheel: started
2026-01-27 00:31:38.726150 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-27 00:31:38.727148 | controller |   Preparing metadata (pyproject.toml): started
2026-01-27 00:31:39.177106 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-27 00:31:39.177278 | 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.
2026-01-27 00:31:39.179813 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-27 00:31:39.340265 | controller | ERROR
2026-01-27 00:31:39.340497 | controller | {
2026-01-27 00:31:39.340531 | controller |   "delta": "0:00:02.757803",
2026-01-27 00:31:39.340553 | controller |   "end": "2026-01-27 00:31:39.241033",
2026-01-27 00:31:39.340573 | controller |   "msg": "non-zero return code",
2026-01-27 00:31:39.340605 | controller |   "rc": 1,
2026-01-27 00:31:39.340623 | controller |   "start": "2026-01-27 00:31:36.483230"
2026-01-27 00:31:39.340641 | controller | }
failure
2026-01-27 00:31:39.342288 | 
2026-01-27 00:31:39.342340 | PLAY RECAP
2026-01-27 00:31:39.342387 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-27 00:31:39.342413 | 
2026-01-27 00:31:39.460735 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-27 00:31:39.461808 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-27 00:31:40.100589 | 
2026-01-27 00:31:40.100757 | PLAY [all]
2026-01-27 00:31:40.123760 | 
2026-01-27 00:31:40.123896 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-27 00:31:40.514184 | controller | changed: non-zero return code
2026-01-27 00:31:40.528818 | 
2026-01-27 00:31:40.529002 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-27 00:31:40.546369 | controller | skipping: Conditional result was False
2026-01-27 00:31:40.555730 | 
2026-01-27 00:31:40.555840 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-27 00:31:40.591402 | 
2026-01-27 00:31:40.591607 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-27 00:31:40.618597 | 
2026-01-27 00:31:40.618873 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-27 00:31:40.634403 | controller | skipping: Conditional result was False
2026-01-27 00:31:40.642536 | 
2026-01-27 00:31:40.642639 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-27 00:31:40.676043 | 
2026-01-27 00:31:40.676274 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-27 00:31:40.701305 | controller | skipping: Conditional result was False
2026-01-27 00:31:40.709945 | 
2026-01-27 00:31:40.710042 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-27 00:31:40.734983 | controller | skipping: Conditional result was False
2026-01-27 00:31:40.743562 | 
2026-01-27 00:31:40.743657 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-27 00:31:40.769052 | controller | skipping: Conditional result was False
2026-01-27 00:31:40.817766 | 
2026-01-27 00:31:40.817924 | PLAY RECAP
2026-01-27 00:31:40.817984 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-27 00:31:40.818014 | 
2026-01-27 00:31:40.928592 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-27 00:31:40.932103 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-27 00:31:41.650587 | 
2026-01-27 00:31:41.650725 | PLAY [all:!appliance*]
2026-01-27 00:31:41.674162 | 
2026-01-27 00:31:41.674278 | TASK [unregister the node]
2026-01-27 00:31:42.207717 | controller | skipping: Conditional result was False
2026-01-27 00:31:42.216843 | 
2026-01-27 00:31:42.216993 | TASK [include_role : fetch-output]
2026-01-27 00:31:42.253539 | controller | ok
2026-01-27 00:31:42.287736 | 
2026-01-27 00:31:42.287876 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-27 00:31:42.333473 | controller | skipping: Conditional result was False
2026-01-27 00:31:42.341152 | 
2026-01-27 00:31:42.341257 | TASK [fetch-output : Set log path for single node]
2026-01-27 00:31:42.382598 | controller | ok
2026-01-27 00:31:42.389844 | 
2026-01-27 00:31:42.389928 | LOOP [fetch-output : Ensure local output dirs]
2026-01-27 00:31:42.770370 | controller -> localhost | ok: "/var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/logs"
2026-01-27 00:31:42.988545 | controller -> localhost | changed: "/var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/artifacts"
2026-01-27 00:31:43.219059 | controller -> localhost | changed: "/var/lib/zuul/builds/a6799d7b0f5d427f9718b7c1018e84e1/work/docs"
2026-01-27 00:31:43.228000 | 
2026-01-27 00:31:43.228117 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-27 00:31:43.906731 | controller | changed:
2026-01-27 00:31:43.908012 | controller | .d..t...... ./
2026-01-27 00:31:43.908111 | controller | cd+++++++++ controller/
2026-01-27 00:31:43.908187 | controller | changed: All items complete
2026-01-27 00:31:43.908231 | 
2026-01-27 00:31:44.480238 | controller | changed: .d..t...... ./
2026-01-27 00:31:45.040049 | controller | changed: .d..t...... ./
2026-01-27 00:31:45.057802 | 
2026-01-27 00:31:45.057927 | TASK [include_role : fetch-output-openshift]
2026-01-27 00:31:45.072343 | controller | skipping: Conditional result was False
2026-01-27 00:31:45.080144 | 
2026-01-27 00:31:45.080258 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-27 00:31:45.109196 | controller | skipping: Conditional result was False
2026-01-27 00:31:45.118823 | controller | skipping: Conditional result was False
2026-01-27 00:31:45.168211 | 
2026-01-27 00:31:45.168381 | PLAY [localhost]
2026-01-27 00:31:45.191135 | 
2026-01-27 00:31:45.191256 | TASK [Run Zuul manifest role]
2026-01-27 00:31:45.210361 | localhost | ok
2026-01-27 00:31:45.224306 | 
2026-01-27 00:31:45.224384 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-27 00:31:45.644750 | localhost | changed
2026-01-27 00:31:45.657094 | 
2026-01-27 00:31:45.657275 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-27 00:31:45.693072 | localhost | ok
2026-01-27 00:31:45.710139 | 
2026-01-27 00:31:45.710274 | TASK [Set zuul-log-path fact]
2026-01-27 00:31:45.731615 | localhost | ok
2026-01-27 00:31:45.745584 | 
2026-01-27 00:31:45.745725 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-27 00:31:45.776655 | localhost | ok
2026-01-27 00:31:45.784933 | 
2026-01-27 00:31:45.785043 | LOOP [Run upload-logs-swift role]
2026-01-27 00:31:45.821116 | localhost | Output suppressed because no_log was given
2026-01-27 00:31:45.845829 | 
2026-01-27 00:31:45.845958 | TASK [Set zuul-log-path fact]
2026-01-27 00:31:45.870423 | localhost | skipping: Conditional result was False
2026-01-27 00:31:45.875490 | 
2026-01-27 00:31:45.875563 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-27 00:31:46.307913 | localhost -> localhost | ok: Runtime: 0:00:00.007601
2026-01-27 00:31:46.326951 | 
2026-01-27 00:31:46.327181 | TASK [upload-logs-swift : Upload logs to swift]