2025-12-29 00:06:54.137812 | Job console starting...
2025-12-29 00:06:54.148636 | Updating repositories
2025-12-29 00:06:54.295770 | Preparing job workspace
2025-12-29 00:06:57.919532 | Running Ansible setup...
2025-12-29 00:07:04.440676 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-29 00:07:05.151155 | 
2025-12-29 00:07:05.151281 | PLAY [localhost]
2025-12-29 00:07:05.160385 | 
2025-12-29 00:07:05.160465 | TASK [Gathering Facts]
2025-12-29 00:07:06.183628 | localhost | ok
2025-12-29 00:07:06.197595 | 
2025-12-29 00:07:06.197979 | TASK [Setup log path fact]
2025-12-29 00:07:06.215409 | localhost | ok
2025-12-29 00:07:06.227733 | 
2025-12-29 00:07:06.227808 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-29 00:07:06.265123 | localhost | ok
2025-12-29 00:07:06.277325 | 
2025-12-29 00:07:06.277449 | TASK [emit-job-header : Print job information]
2025-12-29 00:07:06.305143 | # Job Information
2025-12-29 00:07:06.305292 | Ansible Version: 2.15.12
2025-12-29 00:07:06.305323 | Job: ansible-test-sanity-docker-devel
2025-12-29 00:07:06.305343 | Pipeline: periodic
2025-12-29 00:07:06.305362 | Executor: ze01.softwarefactory-project.io
2025-12-29 00:07:06.305380 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-12-29 00:07:06.305401 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/693/ansible/693ea5a276f646259b1bc3b855b5f816/
2025-12-29 00:07:06.305420 | Event ID: eb0a6e43c3504cb28144f028ea8b0113
2025-12-29 00:07:06.309036 | 
2025-12-29 00:07:06.309097 | LOOP [emit-job-header : Print node information]
2025-12-29 00:07:06.409995 | localhost | ok:
2025-12-29 00:07:06.410226 | localhost | # Node Information
2025-12-29 00:07:06.410254 | localhost | Inventory Hostname: controller
2025-12-29 00:07:06.410273 | localhost | Hostname: np0005571999
2025-12-29 00:07:06.410292 | localhost | Username: zuul
2025-12-29 00:07:06.410315 | localhost | Distro: Fedora 37
2025-12-29 00:07:06.410333 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-12-29 00:07:06.410350 | localhost | Region: ca-ymq-1
2025-12-29 00:07:06.410367 | localhost | Label: ansible-fedora-37-1vcpu
2025-12-29 00:07:06.410384 | localhost | Product Name: OpenStack Nova
2025-12-29 00:07:06.410401 | localhost | Interface IP: 162.253.55.70
2025-12-29 00:07:06.422288 | 
2025-12-29 00:07:06.422414 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-29 00:07:06.811980 | localhost -> localhost | changed
2025-12-29 00:07:06.818421 | 
2025-12-29 00:07:06.818492 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-29 00:07:07.761997 | localhost -> localhost | changed
2025-12-29 00:07:07.786802 | 
2025-12-29 00:07:07.786877 | PLAY [all:!appliance*]
2025-12-29 00:07:07.821716 | 
2025-12-29 00:07:07.821843 | TASK [include_role : start-zuul-console]
2025-12-29 00:07:07.843555 | controller | ok
2025-12-29 00:07:07.857858 | 
2025-12-29 00:07:07.857947 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-29 00:07:08.224603 | controller | ok
2025-12-29 00:07:08.248567 | 
2025-12-29 00:07:08.248712 | TASK [use-our-mirror : Retrieve the IP address]
2025-12-29 00:07:30.521304 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-12-29 00:07:30.528417 | 
2025-12-29 00:07:30.528548 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-12-29 00:07:31.078817 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.092450 | 
2025-12-29 00:07:31.092624 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-12-29 00:07:31.120739 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.137608 | 
2025-12-29 00:07:31.137777 | TASK [use-our-mirror : Create the podman configuration directory]
2025-12-29 00:07:31.164511 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.179798 | 
2025-12-29 00:07:31.179975 | TASK [use-our-mirror : Copy the podman configuration]
2025-12-29 00:07:31.206611 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.222611 | 
2025-12-29 00:07:31.222768 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-12-29 00:07:31.261341 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.270113 | 
2025-12-29 00:07:31.270205 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-12-29 00:07:31.295008 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.307059 | 
2025-12-29 00:07:31.307147 | TASK [Disable Fedora Modular]
2025-12-29 00:07:31.687255 | controller | changed
2025-12-29 00:07:31.702317 | 
2025-12-29 00:07:31.702471 | TASK [Enable EPEL]
2025-12-29 00:07:31.729798 | controller | skipping: Conditional result was False
2025-12-29 00:07:31.744317 | 
2025-12-29 00:07:31.744467 | TASK [Register the RHEL node]
2025-12-29 00:07:32.308430 | 
2025-12-29 00:07:32.308760 | TASK [Show the subscription-manager status]
2025-12-29 00:07:32.853332 | controller | skipping: Conditional result was False
2025-12-29 00:07:32.867410 | 
2025-12-29 00:07:32.867562 | TASK [Enable EPEL on RHEL]
2025-12-29 00:07:33.435798 | controller | skipping: Conditional result was False
2025-12-29 00:07:33.450161 | 
2025-12-29 00:07:33.450311 | TASK [Install git and tox]
2025-12-29 00:08:21.523760 | controller | changed
2025-12-29 00:08:21.544373 | 
2025-12-29 00:08:21.544592 | TASK [include_role : prepare-workspace]
2025-12-29 00:08:21.572667 | controller | ok
2025-12-29 00:08:21.595068 | 
2025-12-29 00:08:21.595207 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-29 00:08:21.840486 | controller | ok
2025-12-29 00:08:21.853138 | 
2025-12-29 00:08:21.853292 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-29 00:08:38.813239 | controller | Output suppressed because no_log was given
2025-12-29 00:08:38.825326 | 
2025-12-29 00:08:38.825444 | TASK [include_role : prepare-workspace-openshift]
2025-12-29 00:08:38.849671 | controller | skipping: Conditional result was False
2025-12-29 00:08:38.874400 | 
2025-12-29 00:08:38.874457 | PLAY [all:!appliance]
2025-12-29 00:08:38.932910 | 
2025-12-29 00:08:38.933044 | TASK [Run add-build-sshkey role (RSA)]
2025-12-29 00:08:38.963150 | controller | ok
2025-12-29 00:08:38.978114 | 
2025-12-29 00:08:38.978187 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-29 00:08:39.256127 | controller -> localhost | ok
2025-12-29 00:08:39.264131 | 
2025-12-29 00:08:39.264238 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-29 00:08:39.317197 | controller | ok
2025-12-29 00:08:39.339610 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-29 00:08:39.348378 | 
2025-12-29 00:08:39.348476 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-29 00:08:39.872504 | controller -> localhost | Generating public/private rsa key pair.
2025-12-29 00:08:39.872724 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_rsa.
2025-12-29 00:08:39.872754 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_rsa.pub.
2025-12-29 00:08:39.872775 | controller -> localhost | The key fingerprint is:
2025-12-29 00:08:39.872795 | controller -> localhost | SHA256:ChzPWTK1EXs4SC2BE54ZTpV9k7hvpIA7PIbj5PnDqsE zuul-build-sshkey
2025-12-29 00:08:39.872841 | controller -> localhost | The key's randomart image is:
2025-12-29 00:08:39.872861 | controller -> localhost | +---[RSA 2048]----+
2025-12-29 00:08:39.872880 | controller -> localhost | |    +++=+o .     |
2025-12-29 00:08:39.872899 | controller -> localhost | |   +o=oo+=+      |
2025-12-29 00:08:39.872918 | controller -> localhost | |    *o+.*o..     |
2025-12-29 00:08:39.872936 | controller -> localhost | |   ..+.=.o.      |
2025-12-29 00:08:39.872955 | controller -> localhost | |   oo.+.S+       |
2025-12-29 00:08:39.872982 | controller -> localhost | |. + *. .. o      |
2025-12-29 00:08:39.873005 | controller -> localhost | |.E = o.  .       |
2025-12-29 00:08:39.873147 | controller -> localhost | | .+ o            |
2025-12-29 00:08:39.873174 | controller -> localhost | |...o..           |
2025-12-29 00:08:39.873195 | controller -> localhost | +----[SHA256]-----+
2025-12-29 00:08:39.873247 | controller -> localhost | ok: Runtime: 0:00:00.129742
2025-12-29 00:08:39.880236 | 
2025-12-29 00:08:39.880321 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-29 00:08:39.901452 | controller | ok
2025-12-29 00:08:39.912489 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-29 00:08:39.922974 | 
2025-12-29 00:08:39.923103 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-29 00:08:39.947324 | controller | skipping: Conditional result was False
2025-12-29 00:08:39.955853 | 
2025-12-29 00:08:39.955955 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-29 00:08:40.413994 | controller | changed
2025-12-29 00:08:40.429585 | 
2025-12-29 00:08:40.429894 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-29 00:08:40.650765 | controller | ok
2025-12-29 00:08:40.657077 | 
2025-12-29 00:08:40.657182 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-29 00:08:41.318286 | controller | changed
2025-12-29 00:08:41.326607 | 
2025-12-29 00:08:41.326697 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-29 00:08:42.012529 | controller | changed
2025-12-29 00:08:42.021454 | 
2025-12-29 00:08:42.021571 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-29 00:08:42.047123 | controller | skipping: Conditional result was False
2025-12-29 00:08:42.059379 | 
2025-12-29 00:08:42.059667 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-29 00:08:42.443648 | controller -> localhost | changed
2025-12-29 00:08:42.455351 | 
2025-12-29 00:08:42.455458 | TASK [add-build-sshkey : Add back temp key]
2025-12-29 00:08:42.705407 | controller -> localhost | Identity added: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_rsa (zuul-build-sshkey)
2025-12-29 00:08:42.705720 | controller -> localhost | ok: Runtime: 0:00:00.007860
2025-12-29 00:08:42.716288 | 
2025-12-29 00:08:42.716382 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-29 00:08:43.077405 | controller | ok
2025-12-29 00:08:43.087416 | 
2025-12-29 00:08:43.087552 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-29 00:08:43.127144 | controller | skipping: Conditional result was False
2025-12-29 00:08:43.148984 | 
2025-12-29 00:08:43.149234 | TASK [Run add-build-sshkey role (ECDSA)]
2025-12-29 00:08:43.188056 | controller | ok
2025-12-29 00:08:43.213552 | 
2025-12-29 00:08:43.213718 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-29 00:08:43.496238 | controller -> localhost | ok
2025-12-29 00:08:43.507586 | 
2025-12-29 00:08:43.507737 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-29 00:08:43.530325 | controller | ok
2025-12-29 00:08:43.542792 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-29 00:08:43.549596 | 
2025-12-29 00:08:43.549661 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-29 00:08:43.860706 | controller -> localhost | Generating public/private ecdsa key pair.
2025-12-29 00:08:43.861117 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_ecdsa.
2025-12-29 00:08:43.861207 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_ecdsa.pub.
2025-12-29 00:08:43.861283 | controller -> localhost | The key fingerprint is:
2025-12-29 00:08:43.861344 | controller -> localhost | SHA256:5+LunR+gQg+jiJPmUbalDpuOl26a7JQNl/TwPyWpSAs zuul-build-sshkey
2025-12-29 00:08:43.861403 | controller -> localhost | The key's randomart image is:
2025-12-29 00:08:43.861495 | controller -> localhost | +---[ECDSA 521]---+
2025-12-29 00:08:43.861563 | controller -> localhost | |                 |
2025-12-29 00:08:43.861623 | controller -> localhost | |                 |
2025-12-29 00:08:43.861680 | controller -> localhost | |   o             |
2025-12-29 00:08:43.861735 | controller -> localhost | |  . =   .        |
2025-12-29 00:08:43.861788 | controller -> localhost | | E * ++oS.o      |
2025-12-29 00:08:43.861846 | controller -> localhost | | oX.*oo+o+ .     |
2025-12-29 00:08:43.861900 | controller -> localhost | |+*.B...o+ . .    |
2025-12-29 00:08:43.861995 | controller -> localhost | |*oX    o.o . .   |
2025-12-29 00:08:43.862103 | controller -> localhost | |*%..   o+ o..    |
2025-12-29 00:08:43.862440 | controller -> localhost | +----[SHA256]-----+
2025-12-29 00:08:43.862619 | controller -> localhost | ok: Runtime: 0:00:00.015471
2025-12-29 00:08:43.882599 | 
2025-12-29 00:08:43.883003 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-29 00:08:43.917678 | controller | ok
2025-12-29 00:08:43.926357 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-29 00:08:43.936492 | 
2025-12-29 00:08:43.936571 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-29 00:08:43.971552 | controller | skipping: Conditional result was False
2025-12-29 00:08:43.984296 | 
2025-12-29 00:08:43.984458 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-29 00:08:44.277097 | controller | changed
2025-12-29 00:08:44.288147 | 
2025-12-29 00:08:44.288314 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-29 00:08:44.513270 | controller | ok
2025-12-29 00:08:44.518905 | 
2025-12-29 00:08:44.518969 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-29 00:08:45.142770 | controller | changed
2025-12-29 00:08:45.148899 | 
2025-12-29 00:08:45.148969 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-29 00:08:45.776349 | controller | changed
2025-12-29 00:08:45.782808 | 
2025-12-29 00:08:45.782877 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-29 00:08:45.817930 | controller | skipping: Conditional result was False
2025-12-29 00:08:45.826579 | 
2025-12-29 00:08:45.826728 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-29 00:08:46.068775 | controller -> localhost | changed
2025-12-29 00:08:46.081486 | 
2025-12-29 00:08:46.081557 | TASK [add-build-sshkey : Add back temp key]
2025-12-29 00:08:46.421534 | controller -> localhost | Identity added: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/693ea5a276f646259b1bc3b855b5f816_id_ecdsa (zuul-build-sshkey)
2025-12-29 00:08:46.421738 | controller -> localhost | ok: Runtime: 0:00:00.010041
2025-12-29 00:08:46.428817 | 
2025-12-29 00:08:46.428889 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-29 00:08:46.632802 | controller | ok
2025-12-29 00:08:46.676765 | 
2025-12-29 00:08:46.676933 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-29 00:08:46.722494 | controller | skipping: Conditional result was False
2025-12-29 00:08:46.738898 | 
2025-12-29 00:08:46.739004 | TASK [include_role : remove-zuul-sshkey]
2025-12-29 00:08:46.764926 | controller | skipping: Conditional result was False
2025-12-29 00:08:46.774694 | 
2025-12-29 00:08:46.774768 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-29 00:08:47.045159 | controller | ok: "logs"
2025-12-29 00:08:47.046206 | controller | ok: All items complete
2025-12-29 00:08:47.046282 | 
2025-12-29 00:08:47.273989 | controller | ok: "artifacts"
2025-12-29 00:08:47.450656 | controller | ok: "docs"
2025-12-29 00:08:47.468044 | 
2025-12-29 00:08:47.468166 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-29 00:08:47.736503 | controller | changed: "logs"
2025-12-29 00:08:47.931128 | controller | changed: "artifacts"
2025-12-29 00:08:48.127383 | controller | changed: "docs"
2025-12-29 00:08:48.207580 | 
2025-12-29 00:08:48.207710 | PLAY RECAP
2025-12-29 00:08:48.207771 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-12-29 00:08:48.207807 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-29 00:08:48.207832 | 
2025-12-29 00:08:48.376346 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-29 00:08:48.377314 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-29 00:08:48.984591 | 
2025-12-29 00:08:48.984735 | PLAY [all]
2025-12-29 00:08:49.039330 | 
2025-12-29 00:08:49.039461 | TASK [Install binary dependencies]
2025-12-29 00:08:49.110065 | controller | ok
2025-12-29 00:08:49.149737 | 
2025-12-29 00:08:49.149920 | TASK [bindep : Include find tasks]
2025-12-29 00:08:49.199111 | controller | ok
2025-12-29 00:08:49.215449 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-29 00:08:49.225972 | 
2025-12-29 00:08:49.226135 | TASK [bindep : Look for bindep.txt]
2025-12-29 00:08:49.599962 | controller | ok
2025-12-29 00:08:49.615554 | 
2025-12-29 00:08:49.615809 | TASK [bindep : Define bindep_file fact]
2025-12-29 00:08:49.642036 | controller | skipping: Conditional result was False
2025-12-29 00:08:49.649936 | 
2025-12-29 00:08:49.650127 | TASK [bindep : Look for other-requirements.txt]
2025-12-29 00:08:49.874443 | controller | ok
2025-12-29 00:08:49.881690 | 
2025-12-29 00:08:49.881765 | TASK [bindep : Define bindep_file fact]
2025-12-29 00:08:49.906226 | controller | skipping: Conditional result was False
2025-12-29 00:08:49.913819 | 
2025-12-29 00:08:49.913897 | TASK [bindep : Look for bindep fallback file]
2025-12-29 00:08:49.937967 | controller | skipping: Conditional result was False
2025-12-29 00:08:49.953446 | 
2025-12-29 00:08:49.953937 | TASK [bindep : Define bindep_file fact]
2025-12-29 00:08:49.980483 | controller | skipping: Conditional result was False
2025-12-29 00:08:49.992823 | 
2025-12-29 00:08:49.993237 | TASK [bindep : Include bindep tasks]
2025-12-29 00:08:50.019011 | controller | skipping: Conditional result was False
2025-12-29 00:08:50.029126 | 
2025-12-29 00:08:50.029253 | TASK [bindep : Include install tasks]
2025-12-29 00:08:50.054759 | controller | skipping: Conditional result was False
2025-12-29 00:08:50.065544 | 
2025-12-29 00:08:50.065644 | LOOP [bindep : Include package tasks]
2025-12-29 00:08:50.135394 | 
2025-12-29 00:08:50.135781 | TASK [Run test-setup role]
2025-12-29 00:08:50.174213 | controller | ok
2025-12-29 00:08:50.196653 | 
2025-12-29 00:08:50.196772 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-29 00:08:50.447292 | controller | ok
2025-12-29 00:08:50.455166 | 
2025-12-29 00:08:50.455268 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-29 00:08:50.996593 | controller | skipping: Conditional result was False
2025-12-29 00:08:51.029316 | 
2025-12-29 00:08:51.029424 | PLAY RECAP
2025-12-29 00:08:51.029468 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-29 00:08:51.029489 | 
2025-12-29 00:08:51.152265 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-29 00:08:51.154353 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-29 00:08:51.813212 | 
2025-12-29 00:08:51.813333 | PLAY [controller]
2025-12-29 00:08:51.833837 | 
2025-12-29 00:08:51.833920 | TASK [Create the /root directory]
2025-12-29 00:08:52.234076 | controller | ok
2025-12-29 00:08:52.242836 | 
2025-12-29 00:08:52.242966 | TASK [Install glibc-langpack-en]
2025-12-29 00:08:56.236133 | controller | ok: Nothing to do
2025-12-29 00:08:56.242443 | 
2025-12-29 00:08:56.242517 | TASK [Ensure controller directory exists]
2025-12-29 00:08:56.471885 | controller | changed
2025-12-29 00:08:56.481900 | 
2025-12-29 00:08:56.482066 | TASK [Install container runtime]
2025-12-29 00:08:56.546704 | controller | ok
2025-12-29 00:08:56.591717 | 
2025-12-29 00:08:56.592004 | LOOP [ensure-podman : Find distribution installation]
2025-12-29 00:08:56.624820 | controller | ok: "/var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-12-29 00:08:56.632920 | controller | included: /var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-12-29 00:08:56.648067 | 
2025-12-29 00:08:56.648224 | TASK [ensure-podman : Install podman (RedHat)]
2025-12-29 00:10:02.280844 | controller | changed
2025-12-29 00:10:02.295380 | 
2025-12-29 00:10:02.295556 | TASK [ensure-podman : Fetch podman version]
2025-12-29 00:10:02.815542 | controller | Client:       Podman Engine
2025-12-29 00:10:02.845441 | controller | Version:      4.6.2
2025-12-29 00:10:02.845579 | controller | API Version:  4.6.2
2025-12-29 00:10:02.845594 | controller | Go Version:   go1.19.12
2025-12-29 00:10:02.845618 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-12-29 00:10:02.845630 | controller | OS/Arch:      linux/amd64
2025-12-29 00:10:03.346107 | controller | ok: Runtime: 0:00:00.162928
2025-12-29 00:10:03.352397 | 
2025-12-29 00:10:03.352467 | TASK [ensure-podman : Print podman version installed]
2025-12-29 00:10:03.389928 | Podman version: Client:       Podman Engine
2025-12-29 00:10:03.390240 | Version:      4.6.2
2025-12-29 00:10:03.390312 | API Version:  4.6.2
2025-12-29 00:10:03.390360 | Go Version:   go1.19.12
2025-12-29 00:10:03.390401 | Built:        Mon Aug 28 19:38:31 2023
2025-12-29 00:10:03.390444 | OS/Arch:      linux/amd64
2025-12-29 00:10:03.403704 | 
2025-12-29 00:10:03.403860 | TASK [ensure-podman : Validate podman engine]
2025-12-29 00:10:03.949982 | controller | skipping: Conditional result was False
2025-12-29 00:10:03.964954 | 
2025-12-29 00:10:03.965139 | TASK [ensure-podman : Set up docker compatability socket]
2025-12-29 00:10:03.992215 | controller | skipping: Conditional result was False
2025-12-29 00:10:04.018521 | 
2025-12-29 00:10:04.018693 | TASK [Ensure python3.8 is present]
2025-12-29 00:10:04.035236 | controller | skipping: Conditional result was False
2025-12-29 00:10:04.053562 | 
2025-12-29 00:10:04.053767 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-12-29 00:10:04.086226 | controller | ok
2025-12-29 00:10:04.116713 | 
2025-12-29 00:10:04.116952 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-12-29 00:10:05.638495 | controller | ok: Nothing to do
2025-12-29 00:10:05.646581 | 
2025-12-29 00:10:05.646683 | TASK [our-ensure-python : Also install python3-devel]
2025-12-29 00:10:15.812177 | controller | changed
2025-12-29 00:10:15.829469 | 
2025-12-29 00:10:15.829671 | TASK [Run ensure-virtualenv role]
2025-12-29 00:10:15.853630 | controller | ok
2025-12-29 00:10:15.879845 | 
2025-12-29 00:10:15.880048 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-12-29 00:10:16.113676 | controller | /usr/bin/virtualenv
2025-12-29 00:10:16.413848 | controller | ok: Runtime: 0:00:00.006840
2025-12-29 00:10:16.423606 | 
2025-12-29 00:10:16.423783 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-12-29 00:10:16.450886 | controller | skipping: Conditional result was False
2025-12-29 00:10:16.451538 | controller | ok: All items complete
2025-12-29 00:10:16.451587 | 
2025-12-29 00:10:16.479434 | 
2025-12-29 00:10:16.479679 | TASK [Find the full path of the Python interpreter]
2025-12-29 00:10:16.780969 | controller | /usr/bin/python3
2025-12-29 00:10:17.080560 | controller | ok
2025-12-29 00:10:17.093305 | 
2025-12-29 00:10:17.093460 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-12-29 00:10:18.083209 | controller | created virtual environment CPython3.11.0.final.0-64 in 521ms
2025-12-29 00:10:18.109145 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-12-29 00:10:18.109161 | 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-29 00:10:18.109170 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-12-29 00:10:18.109190 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-12-29 00:10:18.151527 | controller | changed
2025-12-29 00:10:18.165183 | 
2025-12-29 00:10:18.165325 | TASK [Set selinux package]
2025-12-29 00:10:18.204733 | controller | ok
2025-12-29 00:10:18.217308 | 
2025-12-29 00:10:18.217466 | TASK [Set selinux package (Fedora)]
2025-12-29 00:10:18.273556 | controller | ok
2025-12-29 00:10:18.281205 | 
2025-12-29 00:10:18.281303 | TASK [Install selinux into virtualenv]
2025-12-29 00:10:43.997943 | controller | Collecting selinux-please-lie-to-me
2025-12-29 00:10:56.180649 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-12-29 00:10:56.499889 | controller | Collecting setuptools<50.0.0
2025-12-29 00:10:56.507407 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-12-29 00:10:56.547310 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 24.2 MB/s eta 0:00:00
2025-12-29 00:10:56.629485 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-12-29 00:10:56.629700 | controller |   Attempting uninstall: setuptools
2025-12-29 00:10:56.632219 | controller |     Found existing installation: setuptools 62.6.0
2025-12-29 00:10:56.694580 | controller |     Uninstalling setuptools-62.6.0:
2025-12-29 00:10:56.703811 | controller |       Successfully uninstalled setuptools-62.6.0
2025-12-29 00:10:57.053044 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-12-29 00:11:08.541403 | controller |
2025-12-29 00:11:08.626055 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-29 00:11:08.626095 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-29 00:11:08.857781 | controller | ok: Runtime: 0:00:50.088748
2025-12-29 00:11:08.870914 | 
2025-12-29 00:11:08.871127 | TASK [Install pytest-forked into virtualenv]
2025-12-29 00:11:20.809089 | controller | Collecting pytest-forked
2025-12-29 00:11:33.041164 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-12-29 00:11:33.092766 | controller | Collecting py
2025-12-29 00:11:33.095976 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-12-29 00:11:33.116322 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.5 MB/s eta 0:00:00
2025-12-29 00:11:33.221935 | controller | Collecting pytest>=3.10
2025-12-29 00:11:33.228238 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2025-12-29 00:11:33.244330 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 30.2 MB/s eta 0:00:00
2025-12-29 00:11:33.282264 | controller | Collecting iniconfig>=1.0.1
2025-12-29 00:11:33.286218 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-12-29 00:11:33.328748 | controller | Collecting packaging>=22
2025-12-29 00:11:33.331624 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-12-29 00:11:33.338826 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 17.8 MB/s eta 0:00:00
2025-12-29 00:11:33.375261 | controller | Collecting pluggy<2,>=1.5
2025-12-29 00:11:33.378361 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-12-29 00:11:33.421547 | controller | Collecting pygments>=2.7.2
2025-12-29 00:11:33.424862 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-12-29 00:11:33.462701 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 35.5 MB/s eta 0:00:00
2025-12-29 00:11:33.529858 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-12-29 00:11:34.578491 | 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-29 00:11:34.586898 | controller |
2025-12-29 00:11:34.661274 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-29 00:11:34.661293 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-29 00:11:34.944601 | controller | ok: Runtime: 0:00:25.565933
2025-12-29 00:11:34.954322 | 
2025-12-29 00:11:34.954491 | TASK [Update pip]
2025-12-29 00:11:35.477973 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-12-29 00:11:45.421838 | controller | Collecting pip
2025-12-29 00:12:21.676686 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-12-29 00:12:21.735983 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 33.0 MB/s eta 0:00:00
2025-12-29 00:12:21.805377 | controller | Installing collected packages: pip
2025-12-29 00:12:21.805617 | controller |   Attempting uninstall: pip
2025-12-29 00:12:21.807899 | controller |     Found existing installation: pip 22.2.2
2025-12-29 00:12:21.941653 | controller |     Uninstalling pip-22.2.2:
2025-12-29 00:12:21.956549 | controller |       Successfully uninstalled pip-22.2.2
2025-12-29 00:12:22.770816 | controller | Successfully installed pip-25.3
2025-12-29 00:12:23.024863 | controller | ok: Runtime: 0:00:47.697183
2025-12-29 00:12:23.032042 | 
2025-12-29 00:12:23.032192 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-12-29 00:12:23.252617 | controller | changed
2025-12-29 00:12:23.261115 | 
2025-12-29 00:12:23.261246 | TASK [Install ansible into virtualenv]
2025-12-29 00:12:23.793822 | controller | Processing ./src/github.com/ansible/ansible
2025-12-29 00:12:23.797104 | controller |   Installing build dependencies: started
2025-12-29 00:12:46.943068 | controller |   Installing build dependencies: finished with status 'done'
2025-12-29 00:12:46.944788 | controller |   Getting requirements to build wheel: started
2025-12-29 00:12:47.715305 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-12-29 00:12:47.717291 | controller |   Preparing metadata (pyproject.toml): started
2025-12-29 00:12:48.199559 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-12-29 00:12:48.205968 | 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-29 00:12:48.210892 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-12-29 00:12:48.355871 | controller | ERROR
2025-12-29 00:12:48.356360 | controller | {
2025-12-29 00:12:48.356410 | controller |   "delta": "0:00:24.773642",
2025-12-29 00:12:48.356445 | controller |   "end": "2025-12-29 00:12:48.283292",
2025-12-29 00:12:48.356475 | controller |   "msg": "non-zero return code",
2025-12-29 00:12:48.356523 | controller |   "rc": 1,
2025-12-29 00:12:48.356554 | controller |   "start": "2025-12-29 00:12:23.509650"
2025-12-29 00:12:48.356583 | controller | }
failure
2025-12-29 00:12:48.359230 | 
2025-12-29 00:12:48.359296 | PLAY RECAP
2025-12-29 00:12:48.359446 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-12-29 00:12:48.359475 | 
2025-12-29 00:12:48.540380 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-29 00:12:48.541439 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-29 00:12:49.089380 | 
2025-12-29 00:12:49.089495 | PLAY [all]
2025-12-29 00:12:49.111907 | 
2025-12-29 00:12:49.112002 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-29 00:12:49.392816 | controller | changed: non-zero return code
2025-12-29 00:12:49.399413 | 
2025-12-29 00:12:49.399491 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-29 00:12:49.424887 | controller | skipping: Conditional result was False
2025-12-29 00:12:49.434296 | 
2025-12-29 00:12:49.434507 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-29 00:12:49.462741 | 
2025-12-29 00:12:49.462966 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-29 00:12:49.498533 | 
2025-12-29 00:12:49.498779 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-29 00:12:49.524373 | controller | skipping: Conditional result was False
2025-12-29 00:12:49.536272 | 
2025-12-29 00:12:49.536407 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-29 00:12:49.561605 | 
2025-12-29 00:12:49.561802 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-29 00:12:49.576918 | controller | skipping: Conditional result was False
2025-12-29 00:12:49.587602 | 
2025-12-29 00:12:49.587705 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-29 00:12:49.602766 | controller | skipping: Conditional result was False
2025-12-29 00:12:49.612449 | 
2025-12-29 00:12:49.612591 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-29 00:12:49.629740 | controller | skipping: Conditional result was False
2025-12-29 00:12:49.673909 | 
2025-12-29 00:12:49.674070 | PLAY RECAP
2025-12-29 00:12:49.674118 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-29 00:12:49.674137 | 
2025-12-29 00:12:49.790489 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-29 00:12:49.791389 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-12-29 00:12:50.373263 | 
2025-12-29 00:12:50.373370 | PLAY [all:!appliance*]
2025-12-29 00:12:50.394436 | 
2025-12-29 00:12:50.394512 | TASK [unregister the node]
2025-12-29 00:12:50.925131 | controller | skipping: Conditional result was False
2025-12-29 00:12:50.939920 | 
2025-12-29 00:12:50.940132 | TASK [include_role : fetch-output]
2025-12-29 00:12:51.002154 | controller | ok
2025-12-29 00:12:51.042710 | 
2025-12-29 00:12:51.042839 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-29 00:12:51.098360 | controller | skipping: Conditional result was False
2025-12-29 00:12:51.105469 | 
2025-12-29 00:12:51.105551 | TASK [fetch-output : Set log path for single node]
2025-12-29 00:12:51.140857 | controller | ok
2025-12-29 00:12:51.146510 | 
2025-12-29 00:12:51.146577 | LOOP [fetch-output : Ensure local output dirs]
2025-12-29 00:12:51.597901 | controller -> localhost | ok: "/var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/logs"
2025-12-29 00:12:51.900333 | controller -> localhost | changed: "/var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/artifacts"
2025-12-29 00:12:52.110977 | controller -> localhost | changed: "/var/lib/zuul/builds/693ea5a276f646259b1bc3b855b5f816/work/docs"
2025-12-29 00:12:52.131190 | 
2025-12-29 00:12:52.131358 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-29 00:12:52.842198 | controller | changed:
2025-12-29 00:12:52.842502 | controller | .d..t...... ./
2025-12-29 00:12:52.842540 | controller | cd+++++++++ controller/
2025-12-29 00:12:52.842586 | controller | changed: All items complete
2025-12-29 00:12:52.842615 | 
2025-12-29 00:12:53.371264 | controller | changed: .d..t...... ./
2025-12-29 00:12:53.843713 | controller | changed: .d..t...... ./
2025-12-29 00:12:53.866624 | 
2025-12-29 00:12:53.866738 | TASK [include_role : fetch-output-openshift]
2025-12-29 00:12:53.881148 | controller | skipping: Conditional result was False
2025-12-29 00:12:53.890747 | 
2025-12-29 00:12:53.890852 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-29 00:12:53.916233 | controller | skipping: Conditional result was False
2025-12-29 00:12:53.924404 | controller | skipping: Conditional result was False
2025-12-29 00:12:53.967115 | 
2025-12-29 00:12:53.967214 | PLAY [localhost]
2025-12-29 00:12:53.985060 | 
2025-12-29 00:12:53.985192 | TASK [Run Zuul manifest role]
2025-12-29 00:12:54.015199 | localhost | ok
2025-12-29 00:12:54.029750 | 
2025-12-29 00:12:54.029840 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-29 00:12:54.394196 | localhost | changed
2025-12-29 00:12:54.398860 | 
2025-12-29 00:12:54.398925 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-29 00:12:54.427400 | localhost | ok
2025-12-29 00:12:54.436098 | 
2025-12-29 00:12:54.436171 | TASK [Set zuul-log-path fact]
2025-12-29 00:12:54.454753 | localhost | ok
2025-12-29 00:12:54.469694 | 
2025-12-29 00:12:54.469802 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-29 00:12:54.498472 | localhost | ok
2025-12-29 00:12:54.507515 | 
2025-12-29 00:12:54.507624 | LOOP [Run upload-logs-swift role]
2025-12-29 00:12:54.532583 | localhost | Output suppressed because no_log was given
2025-12-29 00:12:54.558826 | 
2025-12-29 00:12:54.558949 | TASK [Set zuul-log-path fact]
2025-12-29 00:12:54.584085 | localhost | skipping: Conditional result was False
2025-12-29 00:12:54.590014 | 
2025-12-29 00:12:54.590127 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-12-29 00:12:55.038603 | localhost -> localhost | ok: Runtime: 0:00:00.007033
2025-12-29 00:12:55.047193 | 
2025-12-29 00:12:55.047349 | TASK [upload-logs-swift : Upload logs to swift]