2025-10-27 00:06:40.130983 | Job console starting...
2025-10-27 00:06:40.144071 | Updating repositories
2025-10-27 00:06:40.299592 | Preparing job workspace
2025-10-27 00:06:44.168408 | Running Ansible setup...
2025-10-27 00:06:50.084134 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:06:50.689729 | 
2025-10-27 00:06:50.689850 | PLAY [localhost]
2025-10-27 00:06:50.698328 | 
2025-10-27 00:06:50.698636 | TASK [Gathering Facts]
2025-10-27 00:06:51.799637 | localhost | ok
2025-10-27 00:06:51.820059 | 
2025-10-27 00:06:51.820176 | TASK [Setup log path fact]
2025-10-27 00:06:51.853496 | localhost | ok
2025-10-27 00:06:51.872720 | 
2025-10-27 00:06:51.872824 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:06:51.905883 | localhost | ok
2025-10-27 00:06:51.914607 | 
2025-10-27 00:06:51.914692 | TASK [emit-job-header : Print job information]
2025-10-27 00:06:51.966433 | # Job Information
2025-10-27 00:06:51.966650 | Ansible Version: 2.15.12
2025-10-27 00:06:51.966693 | Job: ansible-test-sanity-docker-devel
2025-10-27 00:06:51.966725 | Pipeline: periodic
2025-10-27 00:06:51.966755 | Executor: ze01.softwarefactory-project.io
2025-10-27 00:06:51.966783 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-27 00:06:51.966815 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/111/ansible/11104784744c4e9db1d5570ed147374d/
2025-10-27 00:06:51.966845 | Event ID: 750469794ad743fdb26497abfe8a4902
2025-10-27 00:06:51.971948 | 
2025-10-27 00:06:51.972069 | LOOP [emit-job-header : Print node information]
2025-10-27 00:06:52.104610 | localhost | ok:
2025-10-27 00:06:52.104856 | localhost | # Node Information
2025-10-27 00:06:52.104884 | localhost | Inventory Hostname: controller
2025-10-27 00:06:52.104904 | localhost | Hostname: ip-172-16-198-209
2025-10-27 00:06:52.104923 | localhost | Username: zuul-worker
2025-10-27 00:06:52.104947 | localhost | Distro: Fedora 37
2025-10-27 00:06:52.104968 | localhost | Provider: ansible-us-east-2
2025-10-27 00:06:52.104985 | localhost | Region: us-east-2
2025-10-27 00:06:52.105001 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-27 00:06:52.105045 | localhost | Product Name: t3.small
2025-10-27 00:06:52.105065 | localhost | Interface IP: 3.139.55.153
2025-10-27 00:06:52.122453 | 
2025-10-27 00:06:52.122572 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-27 00:06:52.546535 | localhost -> localhost | changed
2025-10-27 00:06:52.559513 | 
2025-10-27 00:06:52.559657 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-27 00:06:53.469659 | localhost -> localhost | changed
2025-10-27 00:06:53.488459 | 
2025-10-27 00:06:53.488519 | PLAY [all:!appliance*]
2025-10-27 00:06:53.503281 | 
2025-10-27 00:06:53.503343 | TASK [include_role : start-zuul-console]
2025-10-27 00:06:53.532374 | controller | ok
2025-10-27 00:06:53.545935 | 
2025-10-27 00:06:53.546065 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-27 00:06:54.218102 | controller | ok
2025-10-27 00:06:54.238791 | 
2025-10-27 00:06:54.239091 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-27 00:06:58.532114 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-27 00:06:58.541356 | 
2025-10-27 00:06:58.541449 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-27 00:06:58.688811 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.704402 | 
2025-10-27 00:06:58.704562 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-27 00:06:58.732149 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.751286 | 
2025-10-27 00:06:58.751497 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-27 00:06:58.780388 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.796994 | 
2025-10-27 00:06:58.797198 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-27 00:06:58.826258 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.841172 | 
2025-10-27 00:06:58.841341 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-27 00:06:58.867921 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.877578 | 
2025-10-27 00:06:58.877695 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-27 00:06:58.903681 | controller | skipping: Conditional result was False
2025-10-27 00:06:58.923624 | 
2025-10-27 00:06:58.923789 | TASK [Disable Fedora Modular]
2025-10-27 00:06:59.753080 | controller | changed
2025-10-27 00:06:59.758465 | 
2025-10-27 00:06:59.758525 | TASK [Enable EPEL]
2025-10-27 00:06:59.782790 | controller | skipping: Conditional result was False
2025-10-27 00:06:59.789157 | 
2025-10-27 00:06:59.789221 | TASK [Register the RHEL node]
2025-10-27 00:06:59.968900 | 
2025-10-27 00:06:59.969087 | TASK [Show the subscription-manager status]
2025-10-27 00:07:00.116983 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.148361 | 
2025-10-27 00:07:00.148907 | TASK [Enable EPEL on RHEL]
2025-10-27 00:07:00.579437 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.585666 | 
2025-10-27 00:07:00.585746 | TASK [Install git and tox]
2025-10-27 00:08:31.715967 | controller | changed
2025-10-27 00:08:31.723798 | 
2025-10-27 00:08:31.723917 | TASK [include_role : prepare-workspace]
2025-10-27 00:08:31.755263 | controller | ok
2025-10-27 00:08:31.778869 | 
2025-10-27 00:08:31.778985 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-27 00:08:32.274934 | controller | ok
2025-10-27 00:08:32.283997 | 
2025-10-27 00:08:32.284117 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-27 00:08:46.663419 | controller | Output suppressed because no_log was given
2025-10-27 00:08:46.684659 | 
2025-10-27 00:08:46.684815 | TASK [include_role : prepare-workspace-openshift]
2025-10-27 00:08:46.712587 | controller | skipping: Conditional result was False
2025-10-27 00:08:46.806617 | 
2025-10-27 00:08:46.806690 | PLAY [all:!appliance]
2025-10-27 00:08:46.820806 | 
2025-10-27 00:08:46.820905 | TASK [Run add-build-sshkey role (RSA)]
2025-10-27 00:08:46.850172 | controller | ok
2025-10-27 00:08:46.866575 | 
2025-10-27 00:08:46.866706 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:08:47.099147 | controller -> localhost | ok
2025-10-27 00:08:47.105108 | 
2025-10-27 00:08:47.105192 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:08:47.134370 | controller | ok
2025-10-27 00:08:47.150253 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:08:47.156195 | 
2025-10-27 00:08:47.156278 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:08:47.799992 | controller -> localhost | Generating public/private rsa key pair.
2025-10-27 00:08:47.800315 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_rsa.
2025-10-27 00:08:47.800359 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_rsa.pub.
2025-10-27 00:08:47.800388 | controller -> localhost | The key fingerprint is:
2025-10-27 00:08:47.800417 | controller -> localhost | SHA256:ahM9act+E51+m1SJ2PZRtuAXgTYx6Ji77Ynwq9wco98 zuul-build-sshkey
2025-10-27 00:08:47.800445 | controller -> localhost | The key's randomart image is:
2025-10-27 00:08:47.800471 | controller -> localhost | +---[RSA 2048]----+
2025-10-27 00:08:47.800498 | controller -> localhost | |            .oo. |
2025-10-27 00:08:47.800524 | controller -> localhost | |           . +. .|
2025-10-27 00:08:47.800551 | controller -> localhost | |          + ....o|
2025-10-27 00:08:47.800579 | controller -> localhost | |       . + .+ o.=|
2025-10-27 00:08:47.800604 | controller -> localhost | |      . S .o * =.|
2025-10-27 00:08:47.800642 | controller -> localhost | |       = +. + o..|
2025-10-27 00:08:47.800673 | controller -> localhost | |      +.oooo  .. |
2025-10-27 00:08:47.800701 | controller -> localhost | |     ..o*.B.o... |
2025-10-27 00:08:47.800729 | controller -> localhost | |       ++OoE .o. |
2025-10-27 00:08:47.800758 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:08:47.800817 | controller -> localhost | ok: Runtime: 0:00:00.258976
2025-10-27 00:08:47.809773 | 
2025-10-27 00:08:47.809866 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:08:47.834663 | controller | ok
2025-10-27 00:08:47.849934 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:08:47.862571 | 
2025-10-27 00:08:47.862654 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:08:47.886872 | controller | skipping: Conditional result was False
2025-10-27 00:08:47.893541 | 
2025-10-27 00:08:47.893619 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:08:48.512938 | controller | changed
2025-10-27 00:08:48.518263 | 
2025-10-27 00:08:48.518324 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:08:48.853547 | controller | ok
2025-10-27 00:08:48.861187 | 
2025-10-27 00:08:48.861297 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:08:50.110943 | controller | changed
2025-10-27 00:08:50.123887 | 
2025-10-27 00:08:50.124044 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:08:51.402490 | controller | changed
2025-10-27 00:08:51.410156 | 
2025-10-27 00:08:51.410278 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:08:51.435949 | controller | skipping: Conditional result was False
2025-10-27 00:08:51.444343 | 
2025-10-27 00:08:51.444430 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:08:51.806253 | controller -> localhost | changed
2025-10-27 00:08:51.817388 | 
2025-10-27 00:08:51.817483 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:08:52.096098 | controller -> localhost | Identity added: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_rsa (zuul-build-sshkey)
2025-10-27 00:08:52.096339 | controller -> localhost | ok: Runtime: 0:00:00.007175
2025-10-27 00:08:52.102668 | 
2025-10-27 00:08:52.102736 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:08:52.569536 | controller | ok
2025-10-27 00:08:52.581007 | 
2025-10-27 00:08:52.581115 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:08:52.626612 | controller | skipping: Conditional result was False
2025-10-27 00:08:52.638959 | 
2025-10-27 00:08:52.639054 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-27 00:08:52.668698 | controller | ok
2025-10-27 00:08:52.683996 | 
2025-10-27 00:08:52.684082 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:08:52.931155 | controller -> localhost | ok
2025-10-27 00:08:52.937393 | 
2025-10-27 00:08:52.937455 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:08:52.958446 | controller | ok
2025-10-27 00:08:52.968792 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:08:52.974367 | 
2025-10-27 00:08:52.974429 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:08:53.335632 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-27 00:08:53.335840 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_ecdsa.
2025-10-27 00:08:53.335881 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_ecdsa.pub.
2025-10-27 00:08:53.335921 | controller -> localhost | The key fingerprint is:
2025-10-27 00:08:53.335951 | controller -> localhost | SHA256:AJJIM5tDlNoBKYr+S01cp/Fd7rOn9UFY0HOXoo2fh0c zuul-build-sshkey
2025-10-27 00:08:53.335980 | controller -> localhost | The key's randomart image is:
2025-10-27 00:08:53.336007 | controller -> localhost | +---[ECDSA 521]---+
2025-10-27 00:08:53.336060 | controller -> localhost | |+Xo..        .. .|
2025-10-27 00:08:53.336088 | controller -> localhost | |=.B. .       ..+o|
2025-10-27 00:08:53.336114 | controller -> localhost | |== .  .o .  +...+|
2025-10-27 00:08:53.336139 | controller -> localhost | |+ o . ..= .oo.oE |
2025-10-27 00:08:53.336164 | controller -> localhost | |.    o .S. ..o+. |
2025-10-27 00:08:53.336189 | controller -> localhost | | .  o       .+.o |
2025-10-27 00:08:53.336214 | controller -> localhost | |  .. .       ooo |
2025-10-27 00:08:53.336239 | controller -> localhost | |  ..          +.o|
2025-10-27 00:08:53.336264 | controller -> localhost | |   ..        oo .|
2025-10-27 00:08:53.336289 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:08:53.336351 | controller -> localhost | ok: Runtime: 0:00:00.014971
2025-10-27 00:08:53.347220 | 
2025-10-27 00:08:53.347336 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:08:53.370569 | controller | ok
2025-10-27 00:08:53.381048 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:08:53.395601 | 
2025-10-27 00:08:53.395694 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:08:53.420679 | controller | skipping: Conditional result was False
2025-10-27 00:08:53.426590 | 
2025-10-27 00:08:53.426657 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:08:53.870171 | controller | changed
2025-10-27 00:08:53.875856 | 
2025-10-27 00:08:53.875924 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:08:54.244627 | controller | ok
2025-10-27 00:08:54.250003 | 
2025-10-27 00:08:54.250097 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:08:55.794736 | controller | changed
2025-10-27 00:08:55.802854 | 
2025-10-27 00:08:55.802959 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:08:57.156969 | controller | changed
2025-10-27 00:08:57.169827 | 
2025-10-27 00:08:57.170000 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:08:57.198061 | controller | skipping: Conditional result was False
2025-10-27 00:08:57.213048 | 
2025-10-27 00:08:57.213212 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:08:57.486949 | controller -> localhost | changed
2025-10-27 00:08:57.503243 | 
2025-10-27 00:08:57.503362 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:08:57.924048 | controller -> localhost | Identity added: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/11104784744c4e9db1d5570ed147374d_id_ecdsa (zuul-build-sshkey)
2025-10-27 00:08:57.924482 | controller -> localhost | ok: Runtime: 0:00:00.013491
2025-10-27 00:08:57.941452 | 
2025-10-27 00:08:57.941623 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:08:58.561872 | controller | ok
2025-10-27 00:08:58.575552 | 
2025-10-27 00:08:58.576144 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:08:58.615270 | controller | skipping: Conditional result was False
2025-10-27 00:08:58.641723 | 
2025-10-27 00:08:58.641926 | TASK [include_role : remove-zuul-sshkey]
2025-10-27 00:08:58.669378 | controller | skipping: Conditional result was False
2025-10-27 00:08:58.678572 | 
2025-10-27 00:08:58.678669 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-27 00:08:59.059204 | controller | ok: "logs"
2025-10-27 00:08:59.059649 | controller | ok: All items complete
2025-10-27 00:08:59.059714 | 
2025-10-27 00:08:59.342677 | controller | ok: "artifacts"
2025-10-27 00:08:59.638506 | controller | ok: "docs"
2025-10-27 00:08:59.653471 | 
2025-10-27 00:08:59.653671 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-27 00:09:00.002716 | controller | changed: "logs"
2025-10-27 00:09:00.536565 | controller | changed: "artifacts"
2025-10-27 00:09:00.832848 | controller | changed: "docs"
2025-10-27 00:09:00.891116 | 
2025-10-27 00:09:00.891246 | PLAY RECAP
2025-10-27 00:09:00.891304 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-27 00:09:00.891345 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-27 00:09:00.891370 | 
2025-10-27 00:09:01.008381 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:09:01.010185 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:09:01.610292 | 
2025-10-27 00:09:01.610397 | PLAY [all]
2025-10-27 00:09:01.648294 | 
2025-10-27 00:09:01.648387 | TASK [Install binary dependencies]
2025-10-27 00:09:01.730354 | controller | ok
2025-10-27 00:09:01.761469 | 
2025-10-27 00:09:01.761546 | TASK [bindep : Include find tasks]
2025-10-27 00:09:01.800845 | controller | ok
2025-10-27 00:09:01.815332 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-27 00:09:01.821357 | 
2025-10-27 00:09:01.821418 | TASK [bindep : Look for bindep.txt]
2025-10-27 00:09:02.923176 | controller | ok
2025-10-27 00:09:02.931917 | 
2025-10-27 00:09:02.932048 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:02.957468 | controller | skipping: Conditional result was False
2025-10-27 00:09:02.966031 | 
2025-10-27 00:09:02.966147 | TASK [bindep : Look for other-requirements.txt]
2025-10-27 00:09:03.498240 | controller | ok
2025-10-27 00:09:03.510821 | 
2025-10-27 00:09:03.511192 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:03.549352 | controller | skipping: Conditional result was False
2025-10-27 00:09:03.562415 | 
2025-10-27 00:09:03.562558 | TASK [bindep : Look for bindep fallback file]
2025-10-27 00:09:03.599667 | controller | skipping: Conditional result was False
2025-10-27 00:09:03.615071 | 
2025-10-27 00:09:03.615231 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:03.643180 | controller | skipping: Conditional result was False
2025-10-27 00:09:03.655769 | 
2025-10-27 00:09:03.655901 | TASK [bindep : Include bindep tasks]
2025-10-27 00:09:03.682619 | controller | skipping: Conditional result was False
2025-10-27 00:09:03.695461 | 
2025-10-27 00:09:03.695597 | TASK [bindep : Include install tasks]
2025-10-27 00:09:03.723411 | controller | skipping: Conditional result was False
2025-10-27 00:09:03.736619 | 
2025-10-27 00:09:03.736762 | LOOP [bindep : Include package tasks]
2025-10-27 00:09:03.817295 | 
2025-10-27 00:09:03.817574 | TASK [Run test-setup role]
2025-10-27 00:09:03.845209 | controller | ok
2025-10-27 00:09:03.876243 | 
2025-10-27 00:09:03.876367 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-27 00:09:04.802921 | controller | ok
2025-10-27 00:09:04.811278 | 
2025-10-27 00:09:04.811353 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-27 00:09:04.974356 | controller | skipping: Conditional result was False
2025-10-27 00:09:05.007187 | 
2025-10-27 00:09:05.007309 | PLAY RECAP
2025-10-27 00:09:05.007359 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:09:05.007380 | 
2025-10-27 00:09:05.141196 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:09:05.142031 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:09:05.697261 | 
2025-10-27 00:09:05.697391 | PLAY [controller]
2025-10-27 00:09:05.717651 | 
2025-10-27 00:09:05.717734 | TASK [Create the /root directory]
2025-10-27 00:09:06.444919 | controller | ok
2025-10-27 00:09:06.453754 | 
2025-10-27 00:09:06.453868 | TASK [Install glibc-langpack-en]
2025-10-27 00:09:14.443851 | controller | ok: Nothing to do
2025-10-27 00:09:14.457855 | 
2025-10-27 00:09:14.458091 | TASK [Ensure controller directory exists]
2025-10-27 00:09:14.984639 | controller | changed
2025-10-27 00:09:14.993372 | 
2025-10-27 00:09:14.993502 | TASK [Install container runtime]
2025-10-27 00:09:15.072206 | controller | ok
2025-10-27 00:09:15.131914 | 
2025-10-27 00:09:15.132094 | LOOP [ensure-podman : Find distribution installation]
2025-10-27 00:09:15.186482 | controller | ok: "/var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-27 00:09:15.203447 | controller | included: /var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-27 00:09:15.211882 | 
2025-10-27 00:09:15.212095 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-27 00:10:41.797160 | controller | changed
2025-10-27 00:10:41.812847 | 
2025-10-27 00:10:41.813039 | TASK [ensure-podman : Fetch podman version]
2025-10-27 00:10:42.555970 | controller | Client:       Podman Engine
2025-10-27 00:10:42.556048 | controller | Version:      4.6.2
2025-10-27 00:10:42.556078 | controller | API Version:  4.6.2
2025-10-27 00:10:42.556104 | controller | Go Version:   go1.19.12
2025-10-27 00:10:42.556141 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:10:42.556168 | controller | OS/Arch:      linux/amd64
2025-10-27 00:10:42.983226 | controller | ok: Runtime: 0:00:00.203021
2025-10-27 00:10:42.999135 | 
2025-10-27 00:10:42.999375 | TASK [ensure-podman : Print podman version installed]
2025-10-27 00:10:43.040266 | Podman version: Client:       Podman Engine
2025-10-27 00:10:43.040559 | Version:      4.6.2
2025-10-27 00:10:43.040625 | API Version:  4.6.2
2025-10-27 00:10:43.040673 | Go Version:   go1.19.12
2025-10-27 00:10:43.040723 | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:10:43.040792 | OS/Arch:      linux/amd64
2025-10-27 00:10:43.055547 | 
2025-10-27 00:10:43.055755 | TASK [ensure-podman : Validate podman engine]
2025-10-27 00:10:43.211472 | controller | skipping: Conditional result was False
2025-10-27 00:10:43.225298 | 
2025-10-27 00:10:43.225439 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-27 00:10:43.252590 | controller | skipping: Conditional result was False
2025-10-27 00:10:43.278874 | 
2025-10-27 00:10:43.279088 | TASK [Ensure python3.8 is present]
2025-10-27 00:10:43.306059 | controller | skipping: Conditional result was False
2025-10-27 00:10:43.319669 | 
2025-10-27 00:10:43.319828 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-27 00:10:43.361150 | controller | ok
2025-10-27 00:10:43.392709 | 
2025-10-27 00:10:43.392814 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-27 00:10:47.441556 | controller | ok: Nothing to do
2025-10-27 00:10:47.454642 | 
2025-10-27 00:10:47.454819 | TASK [our-ensure-python : Also install python3-devel]
2025-10-27 00:11:01.122696 | controller | changed
2025-10-27 00:11:01.137493 | 
2025-10-27 00:11:01.137601 | TASK [Run ensure-virtualenv role]
2025-10-27 00:11:01.158703 | controller | ok
2025-10-27 00:11:01.201644 | 
2025-10-27 00:11:01.201834 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-27 00:11:02.365199 | controller | /usr/bin/virtualenv
2025-10-27 00:11:02.843471 | controller | ok: Runtime: 0:00:00.018925
2025-10-27 00:11:02.856713 | 
2025-10-27 00:11:02.856931 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-27 00:11:02.895363 | controller | skipping: Conditional result was False
2025-10-27 00:11:02.895898 | controller | ok: All items complete
2025-10-27 00:11:02.895976 | 
2025-10-27 00:11:02.936081 | 
2025-10-27 00:11:02.936317 | TASK [Find the full path of the Python interpreter]
2025-10-27 00:11:03.688296 | controller | /usr/bin/python3
2025-10-27 00:11:04.160713 | controller | ok
2025-10-27 00:11:04.172882 | 
2025-10-27 00:11:04.173090 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-27 00:11:05.765337 | controller | created virtual environment CPython3.11.0.final.0-64 in 821ms
2025-10-27 00:11:05.824579 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-27 00:11:05.824877 | 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-worker/.local/share/virtualenv)
2025-10-27 00:11:05.824897 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-27 00:11:05.824920 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-27 00:11:06.343537 | controller | changed
2025-10-27 00:11:06.355700 | 
2025-10-27 00:11:06.355836 | TASK [Set selinux package]
2025-10-27 00:11:06.382901 | controller | ok
2025-10-27 00:11:06.393589 | 
2025-10-27 00:11:06.393713 | TASK [Set selinux package (Fedora)]
2025-10-27 00:11:06.429749 | controller | ok
2025-10-27 00:11:06.437527 | 
2025-10-27 00:11:06.437653 | TASK [Install selinux into virtualenv]
2025-10-27 00:11:09.065119 | controller | Collecting selinux-please-lie-to-me
2025-10-27 00:11:09.155310 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-27 00:11:09.690317 | controller | Collecting setuptools<50.0.0
2025-10-27 00:11:09.707565 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-27 00:11:09.815261 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.8 MB/s eta 0:00:00
2025-10-27 00:11:09.973724 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-27 00:11:09.974157 | controller |   Attempting uninstall: setuptools
2025-10-27 00:11:09.979079 | controller |     Found existing installation: setuptools 62.6.0
2025-10-27 00:11:10.091492 | controller |     Uninstalling setuptools-62.6.0:
2025-10-27 00:11:10.106679 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-27 00:11:10.863413 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-27 00:11:11.078016 | controller |
2025-10-27 00:11:11.295721 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:11:11.295774 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:11:11.597847 | controller | ok: Runtime: 0:00:04.393365
2025-10-27 00:11:11.611252 | 
2025-10-27 00:11:11.611428 | TASK [Install pytest-forked into virtualenv]
2025-10-27 00:11:12.848079 | controller | Collecting pytest-forked
2025-10-27 00:11:12.936275 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-27 00:11:13.000761 | controller | Collecting py
2025-10-27 00:11:13.013516 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-27 00:11:13.052421 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.8 MB/s eta 0:00:00
2025-10-27 00:11:13.228371 | controller | Collecting pytest>=3.10
2025-10-27 00:11:13.243023 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-27 00:11:13.306063 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.1 MB/s eta 0:00:00
2025-10-27 00:11:13.364774 | controller | Collecting iniconfig>=1
2025-10-27 00:11:13.377329 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-27 00:11:13.445484 | controller | Collecting packaging>=20
2025-10-27 00:11:13.457419 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-27 00:11:13.474407 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.3 MB/s eta 0:00:00
2025-10-27 00:11:13.524570 | controller | Collecting pluggy<2,>=1.5
2025-10-27 00:11:13.537959 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-27 00:11:13.613259 | controller | Collecting pygments>=2.7.2
2025-10-27 00:11:13.625384 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-27 00:11:13.745554 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.4 MB/s eta 0:00:00
2025-10-27 00:11:13.880711 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-27 00:11:16.174147 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-27 00:11:16.190276 | controller |
2025-10-27 00:11:16.381545 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:11:16.381597 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:11:16.776820 | controller | ok: Runtime: 0:00:04.275688
2025-10-27 00:11:16.782917 | 
2025-10-27 00:11:16.783005 | TASK [Update pip]
2025-10-27 00:11:17.917943 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-27 00:11:18.172061 | controller | Collecting pip
2025-10-27 00:11:18.273851 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-27 00:11:18.507781 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 7.8 MB/s eta 0:00:00
2025-10-27 00:11:18.651461 | controller | Installing collected packages: pip
2025-10-27 00:11:18.651871 | controller |   Attempting uninstall: pip
2025-10-27 00:11:18.656339 | controller |     Found existing installation: pip 22.2.2
2025-10-27 00:11:18.914502 | controller |     Uninstalling pip-22.2.2:
2025-10-27 00:11:18.944381 | controller |       Successfully uninstalled pip-22.2.2
2025-10-27 00:11:20.700766 | controller | Successfully installed pip-25.3
2025-10-27 00:11:21.432859 | controller | ok: Runtime: 0:00:03.581623
2025-10-27 00:11:21.439186 | 
2025-10-27 00:11:21.439266 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-27 00:11:21.966304 | controller | changed
2025-10-27 00:11:21.971273 | 
2025-10-27 00:11:21.971334 | TASK [Install ansible into virtualenv]
2025-10-27 00:11:22.969345 | controller | Processing ./src/github.com/ansible/ansible
2025-10-27 00:11:22.975704 | controller |   Installing build dependencies: started
2025-10-27 00:11:24.894801 | controller |   Installing build dependencies: finished with status 'done'
2025-10-27 00:11:26.441287 | controller |   Getting requirements to build wheel: started
2025-10-27 00:11:26.441351 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-27 00:11:26.443036 | controller |   Preparing metadata (pyproject.toml): started
2025-10-27 00:11:27.370306 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-27 00:11:27.373381 | 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-10-27 00:11:27.378212 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-27 00:11:27.612184 | controller | ERROR
2025-10-27 00:11:27.612426 | controller | {
2025-10-27 00:11:27.612478 | controller |   "delta": "0:00:05.130699",
2025-10-27 00:11:27.612521 | controller |   "end": "2025-10-27 00:11:27.527597",
2025-10-27 00:11:27.612558 | controller |   "msg": "non-zero return code",
2025-10-27 00:11:27.612598 | controller |   "rc": 1,
2025-10-27 00:11:27.612634 | controller |   "start": "2025-10-27 00:11:22.396898"
2025-10-27 00:11:27.612672 | controller | }
failure
2025-10-27 00:11:27.615391 | 
2025-10-27 00:11:27.615464 | PLAY RECAP
2025-10-27 00:11:27.615518 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-27 00:11:27.615546 | 
2025-10-27 00:11:27.744480 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:11:27.746884 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:11:28.389736 | 
2025-10-27 00:11:28.389863 | PLAY [all]
2025-10-27 00:11:28.412380 | 
2025-10-27 00:11:28.412525 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-27 00:11:29.181083 | controller | changed: non-zero return code
2025-10-27 00:11:29.190315 | 
2025-10-27 00:11:29.190490 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-27 00:11:29.215907 | controller | skipping: Conditional result was False
2025-10-27 00:11:29.227227 | 
2025-10-27 00:11:29.227418 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-27 00:11:29.266827 | 
2025-10-27 00:11:29.267108 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-27 00:11:29.295821 | 
2025-10-27 00:11:29.296067 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-27 00:11:29.321834 | controller | skipping: Conditional result was False
2025-10-27 00:11:29.330754 | 
2025-10-27 00:11:29.330925 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-27 00:11:29.366996 | 
2025-10-27 00:11:29.367222 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-27 00:11:29.392719 | controller | skipping: Conditional result was False
2025-10-27 00:11:29.402891 | 
2025-10-27 00:11:29.403063 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-27 00:11:29.428572 | controller | skipping: Conditional result was False
2025-10-27 00:11:29.439468 | 
2025-10-27 00:11:29.439651 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-27 00:11:29.464981 | controller | skipping: Conditional result was False
2025-10-27 00:11:29.503678 | 
2025-10-27 00:11:29.503823 | PLAY RECAP
2025-10-27 00:11:29.503912 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:11:29.503969 | 
2025-10-27 00:11:29.605281 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:11:29.607253 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-27 00:11:30.180284 | 
2025-10-27 00:11:30.180399 | PLAY [all:!appliance*]
2025-10-27 00:11:30.201795 | 
2025-10-27 00:11:30.201918 | TASK [unregister the node]
2025-10-27 00:11:30.342279 | controller | skipping: Conditional result was False
2025-10-27 00:11:30.356262 | 
2025-10-27 00:11:30.356529 | TASK [include_role : fetch-output]
2025-10-27 00:11:30.391406 | controller | ok
2025-10-27 00:11:30.417524 | 
2025-10-27 00:11:30.417658 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-27 00:11:30.484315 | controller | skipping: Conditional result was False
2025-10-27 00:11:30.491625 | 
2025-10-27 00:11:30.491783 | TASK [fetch-output : Set log path for single node]
2025-10-27 00:11:30.523866 | controller | ok
2025-10-27 00:11:30.530329 | 
2025-10-27 00:11:30.530488 | LOOP [fetch-output : Ensure local output dirs]
2025-10-27 00:11:30.977669 | controller -> localhost | ok: "/var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/logs"
2025-10-27 00:11:31.231787 | controller -> localhost | changed: "/var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/artifacts"
2025-10-27 00:11:31.493347 | controller -> localhost | changed: "/var/lib/zuul/builds/11104784744c4e9db1d5570ed147374d/work/docs"
2025-10-27 00:11:31.510734 | 
2025-10-27 00:11:31.510965 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-27 00:11:32.698976 | controller | changed:
2025-10-27 00:11:32.699223 | controller | .d..t...... ./
2025-10-27 00:11:32.699258 | controller | cd+++++++++ controller/
2025-10-27 00:11:32.699300 | controller | changed: All items complete
2025-10-27 00:11:32.699325 | 
2025-10-27 00:11:33.739570 | controller | changed: .d..t...... ./
2025-10-27 00:11:34.922555 | controller | changed: .d..t...... ./
2025-10-27 00:11:34.958101 | 
2025-10-27 00:11:34.958259 | TASK [include_role : fetch-output-openshift]
2025-10-27 00:11:34.972898 | controller | skipping: Conditional result was False
2025-10-27 00:11:34.982386 | 
2025-10-27 00:11:34.982531 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-27 00:11:35.028505 | controller | skipping: Conditional result was False
2025-10-27 00:11:35.039574 | controller | skipping: Conditional result was False
2025-10-27 00:11:35.070269 | 
2025-10-27 00:11:35.070386 | PLAY [localhost]
2025-10-27 00:11:35.085056 | 
2025-10-27 00:11:35.085185 | TASK [Run Zuul manifest role]
2025-10-27 00:11:35.104101 | localhost | ok
2025-10-27 00:11:35.120881 | 
2025-10-27 00:11:35.121036 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-27 00:11:35.509456 | localhost | changed
2025-10-27 00:11:35.516815 | 
2025-10-27 00:11:35.516914 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-27 00:11:35.548728 | localhost | ok
2025-10-27 00:11:35.561452 | 
2025-10-27 00:11:35.561568 | TASK [Set zuul-log-path fact]
2025-10-27 00:11:35.586524 | localhost | ok
2025-10-27 00:11:35.614227 | 
2025-10-27 00:11:35.614363 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:11:35.655868 | localhost | ok
2025-10-27 00:11:35.672859 | 
2025-10-27 00:11:35.673046 | LOOP [Run upload-logs-swift role]
2025-10-27 00:11:35.721408 | localhost | Output suppressed because no_log was given
2025-10-27 00:11:35.764395 | 
2025-10-27 00:11:35.764588 | TASK [Set zuul-log-path fact]
2025-10-27 00:11:35.800334 | localhost | skipping: Conditional result was False
2025-10-27 00:11:35.805847 | 
2025-10-27 00:11:35.805919 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-27 00:11:36.281558 | localhost -> localhost | ok: Runtime: 0:00:00.009711
2025-10-27 00:11:36.294795 | 
2025-10-27 00:11:36.294945 | TASK [upload-logs-swift : Upload logs to swift]