2025-10-20 00:12:05.036496 | Job console starting...
2025-10-20 00:12:05.047544 | Updating repositories
2025-10-20 00:12:05.188879 | Preparing job workspace
2025-10-20 00:12:09.373978 | Running Ansible setup...
2025-10-20 00:12:15.806029 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-20 00:12:16.417090 | 
2025-10-20 00:12:16.417355 | PLAY [localhost]
2025-10-20 00:12:16.426512 | 
2025-10-20 00:12:16.426609 | TASK [Gathering Facts]
2025-10-20 00:12:17.423622 | localhost | ok
2025-10-20 00:12:17.447294 | 
2025-10-20 00:12:17.447496 | TASK [Setup log path fact]
2025-10-20 00:12:17.469317 | localhost | ok
2025-10-20 00:12:17.489414 | 
2025-10-20 00:12:17.489560 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-20 00:12:17.519275 | localhost | ok
2025-10-20 00:12:17.527602 | 
2025-10-20 00:12:17.527675 | TASK [emit-job-header : Print job information]
2025-10-20 00:12:17.565667 | # Job Information
2025-10-20 00:12:17.565857 | Ansible Version: 2.15.12
2025-10-20 00:12:17.565890 | Job: ansible-test-sanity-docker-milestone
2025-10-20 00:12:17.565910 | Pipeline: periodic
2025-10-20 00:12:17.565928 | Executor: ze03.softwarefactory-project.io
2025-10-20 00:12:17.565944 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-20 00:12:17.565964 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/1bc/ansible/1bc2a27e9b96453c84786653f200d95b/
2025-10-20 00:12:17.565984 | Event ID: 328e9597672940b996d379e8913dc261
2025-10-20 00:12:17.570064 | 
2025-10-20 00:12:17.570129 | LOOP [emit-job-header : Print node information]
2025-10-20 00:12:17.728101 | localhost | ok:
2025-10-20 00:12:17.728419 | localhost | # Node Information
2025-10-20 00:12:17.728492 | localhost | Inventory Hostname: controller
2025-10-20 00:12:17.728545 | localhost | Hostname: ip-172-16-213-109
2025-10-20 00:12:17.728594 | localhost | Username: zuul-worker
2025-10-20 00:12:17.728646 | localhost | Distro: Fedora 37
2025-10-20 00:12:17.728694 | localhost | Provider: ansible-us-east-2
2025-10-20 00:12:17.728781 | localhost | Region: us-east-2
2025-10-20 00:12:17.728831 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-20 00:12:17.728876 | localhost | Product Name: t3.small
2025-10-20 00:12:17.728921 | localhost | Interface IP: 18.222.214.177
2025-10-20 00:12:17.748175 | 
2025-10-20 00:12:17.748303 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-20 00:12:18.230208 | localhost -> localhost | changed
2025-10-20 00:12:18.244043 | 
2025-10-20 00:12:18.244234 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-20 00:12:19.083929 | localhost -> localhost | changed
2025-10-20 00:12:19.104639 | 
2025-10-20 00:12:19.104949 | PLAY [all:!appliance*]
2025-10-20 00:12:19.121247 | 
2025-10-20 00:12:19.121354 | TASK [include_role : start-zuul-console]
2025-10-20 00:12:19.140755 | controller | ok
2025-10-20 00:12:19.154570 | 
2025-10-20 00:12:19.154671 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-20 00:12:19.843538 | controller | ok
2025-10-20 00:12:19.867161 | 
2025-10-20 00:12:19.867370 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-20 00:12:21.693687 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-20 00:12:21.704921 | 
2025-10-20 00:12:21.705995 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-20 00:12:21.863123 | controller | skipping: Conditional result was False
2025-10-20 00:12:21.873373 | 
2025-10-20 00:12:21.873509 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-20 00:12:21.900006 | controller | skipping: Conditional result was False
2025-10-20 00:12:21.912937 | 
2025-10-20 00:12:21.913082 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-20 00:12:21.928951 | controller | skipping: Conditional result was False
2025-10-20 00:12:21.939152 | 
2025-10-20 00:12:21.939264 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-20 00:12:21.965113 | controller | skipping: Conditional result was False
2025-10-20 00:12:21.974275 | 
2025-10-20 00:12:21.974448 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-20 00:12:21.999742 | controller | skipping: Conditional result was False
2025-10-20 00:12:22.009154 | 
2025-10-20 00:12:22.009254 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-20 00:12:22.035101 | controller | skipping: Conditional result was False
2025-10-20 00:12:22.051639 | 
2025-10-20 00:12:22.051773 | TASK [Disable Fedora Modular]
2025-10-20 00:12:22.941828 | controller | changed
2025-10-20 00:12:22.951839 | 
2025-10-20 00:12:22.951979 | TASK [Enable EPEL]
2025-10-20 00:12:22.977898 | controller | skipping: Conditional result was False
2025-10-20 00:12:22.987158 | 
2025-10-20 00:12:22.987307 | TASK [Register the RHEL node]
2025-10-20 00:12:23.149566 | 
2025-10-20 00:12:23.149864 | TASK [Show the subscription-manager status]
2025-10-20 00:12:23.368599 | controller | skipping: Conditional result was False
2025-10-20 00:12:23.378312 | 
2025-10-20 00:12:23.378430 | TASK [Enable EPEL on RHEL]
2025-10-20 00:12:23.546576 | controller | skipping: Conditional result was False
2025-10-20 00:12:23.563486 | 
2025-10-20 00:12:23.563687 | TASK [Install git and tox]
2025-10-20 00:13:59.123088 | controller | changed
2025-10-20 00:13:59.135659 | 
2025-10-20 00:13:59.135826 | TASK [include_role : prepare-workspace]
2025-10-20 00:13:59.167077 | controller | ok
2025-10-20 00:13:59.200488 | 
2025-10-20 00:13:59.200635 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-20 00:13:59.782865 | controller | ok
2025-10-20 00:13:59.788989 | 
2025-10-20 00:13:59.789056 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-20 00:14:13.568820 | controller | Output suppressed because no_log was given
2025-10-20 00:14:13.581492 | 
2025-10-20 00:14:13.581604 | TASK [include_role : prepare-workspace-openshift]
2025-10-20 00:14:13.606752 | controller | skipping: Conditional result was False
2025-10-20 00:14:13.632970 | 
2025-10-20 00:14:13.633078 | PLAY [all:!appliance]
2025-10-20 00:14:13.703565 | 
2025-10-20 00:14:13.703923 | TASK [Run add-build-sshkey role (RSA)]
2025-10-20 00:14:13.735190 | controller | ok
2025-10-20 00:14:13.757282 | 
2025-10-20 00:14:13.757374 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-20 00:14:14.049151 | controller -> localhost | ok
2025-10-20 00:14:14.063887 | 
2025-10-20 00:14:14.064049 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-20 00:14:14.102972 | controller | ok
2025-10-20 00:14:14.130394 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-20 00:14:14.138580 | 
2025-10-20 00:14:14.138665 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-20 00:14:14.862153 | controller -> localhost | Generating public/private rsa key pair.
2025-10-20 00:14:14.862427 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_rsa.
2025-10-20 00:14:14.862457 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_rsa.pub.
2025-10-20 00:14:14.862478 | controller -> localhost | The key fingerprint is:
2025-10-20 00:14:14.862496 | controller -> localhost | SHA256:hMT+Oxc2v8UsGNAZ1Vq224gPY8uX5Efn5ypKsaiZ34U zuul-build-sshkey
2025-10-20 00:14:14.862514 | controller -> localhost | The key's randomart image is:
2025-10-20 00:14:14.862531 | controller -> localhost | +---[RSA 2048]----+
2025-10-20 00:14:14.862548 | controller -> localhost | |     ..   ....   |
2025-10-20 00:14:14.862566 | controller -> localhost | |     ... . o  +  |
2025-10-20 00:14:14.862582 | controller -> localhost | |     .. o o  + . |
2025-10-20 00:14:14.862599 | controller -> localhost | |      .. .  . .  |
2025-10-20 00:14:14.862615 | controller -> localhost | |       .S o  . + |
2025-10-20 00:14:14.862640 | controller -> localhost | |        ..+*=o+ +|
2025-10-20 00:14:14.862659 | controller -> localhost | |        .oE*oB++.|
2025-10-20 00:14:14.862676 | controller -> localhost | |       +oo..=o= +|
2025-10-20 00:14:14.862693 | controller -> localhost | |      +..oo..+.+o|
2025-10-20 00:14:14.862712 | controller -> localhost | +----[SHA256]-----+
2025-10-20 00:14:14.862779 | controller -> localhost | ok: Runtime: 0:00:00.292323
2025-10-20 00:14:14.878512 | 
2025-10-20 00:14:14.878614 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-20 00:14:14.926619 | controller | ok
2025-10-20 00:14:14.938708 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-20 00:14:14.948094 | 
2025-10-20 00:14:14.948201 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-20 00:14:14.973335 | controller | skipping: Conditional result was False
2025-10-20 00:14:14.980803 | 
2025-10-20 00:14:14.980925 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-20 00:14:15.829241 | controller | changed
2025-10-20 00:14:15.835056 | 
2025-10-20 00:14:15.835143 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-20 00:14:16.183686 | controller | ok
2025-10-20 00:14:16.199754 | 
2025-10-20 00:14:16.200150 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-20 00:14:17.553867 | controller | changed
2025-10-20 00:14:17.568576 | 
2025-10-20 00:14:17.568811 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-20 00:14:18.929546 | controller | changed
2025-10-20 00:14:18.944928 | 
2025-10-20 00:14:18.945024 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-20 00:14:18.970158 | controller | skipping: Conditional result was False
2025-10-20 00:14:18.980828 | 
2025-10-20 00:14:18.980955 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-20 00:14:19.395215 | controller -> localhost | changed
2025-10-20 00:14:19.410835 | 
2025-10-20 00:14:19.410989 | TASK [add-build-sshkey : Add back temp key]
2025-10-20 00:14:19.692789 | controller -> localhost | Identity added: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_rsa (zuul-build-sshkey)
2025-10-20 00:14:19.693117 | controller -> localhost | ok: Runtime: 0:00:00.010252
2025-10-20 00:14:19.702385 | 
2025-10-20 00:14:19.702489 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-20 00:14:20.224552 | controller | ok
2025-10-20 00:14:20.239487 | 
2025-10-20 00:14:20.239681 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-20 00:14:20.289191 | controller | skipping: Conditional result was False
2025-10-20 00:14:20.301347 | 
2025-10-20 00:14:20.301437 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-20 00:14:20.330695 | controller | ok
2025-10-20 00:14:20.350011 | 
2025-10-20 00:14:20.350119 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-20 00:14:20.629558 | controller -> localhost | ok
2025-10-20 00:14:20.637589 | 
2025-10-20 00:14:20.637713 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-20 00:14:20.667223 | controller | ok
2025-10-20 00:14:20.678743 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-20 00:14:20.685755 | 
2025-10-20 00:14:20.685848 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-20 00:14:20.987203 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-20 00:14:20.987497 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_ecdsa.
2025-10-20 00:14:20.987547 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_ecdsa.pub.
2025-10-20 00:14:20.987597 | controller -> localhost | The key fingerprint is:
2025-10-20 00:14:20.987636 | controller -> localhost | SHA256:rh5rVXgaa2b9Spe4tTqMUReQC+ySfD7q8/Kdtg2rgQk zuul-build-sshkey
2025-10-20 00:14:20.987675 | controller -> localhost | The key's randomart image is:
2025-10-20 00:14:20.987714 | controller -> localhost | +---[ECDSA 521]---+
2025-10-20 00:14:20.987824 | controller -> localhost | |       .  .o     |
2025-10-20 00:14:20.987863 | controller -> localhost | |        o . .    |
2025-10-20 00:14:20.987896 | controller -> localhost | |     . o o . .   |
2025-10-20 00:14:20.987930 | controller -> localhost | |      + = = .    |
2025-10-20 00:14:20.987965 | controller -> localhost | |    E  +SO .     |
2025-10-20 00:14:20.988000 | controller -> localhost | |     . +@ .. .   |
2025-10-20 00:14:20.988035 | controller -> localhost | |      +*o=+.+    |
2025-10-20 00:14:20.988070 | controller -> localhost | |      =+.++O..   |
2025-10-20 00:14:20.988104 | controller -> localhost | |     +==+oO=o    |
2025-10-20 00:14:20.988138 | controller -> localhost | +----[SHA256]-----+
2025-10-20 00:14:20.988220 | controller -> localhost | ok: Runtime: 0:00:00.009975
2025-10-20 00:14:20.998704 | 
2025-10-20 00:14:20.998866 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-20 00:14:21.032587 | controller | ok
2025-10-20 00:14:21.043276 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-20 00:14:21.057454 | 
2025-10-20 00:14:21.057568 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-20 00:14:21.082691 | controller | skipping: Conditional result was False
2025-10-20 00:14:21.089624 | 
2025-10-20 00:14:21.089705 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-20 00:14:21.570170 | controller | changed
2025-10-20 00:14:21.586362 | 
2025-10-20 00:14:21.586542 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-20 00:14:21.965721 | controller | ok
2025-10-20 00:14:21.981946 | 
2025-10-20 00:14:21.982145 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-20 00:14:23.293073 | controller | changed
2025-10-20 00:14:23.301304 | 
2025-10-20 00:14:23.301418 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-20 00:14:24.666746 | controller | changed
2025-10-20 00:14:24.674846 | 
2025-10-20 00:14:24.674935 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-20 00:14:24.709939 | controller | skipping: Conditional result was False
2025-10-20 00:14:24.719324 | 
2025-10-20 00:14:24.719413 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-20 00:14:25.003196 | controller -> localhost | changed
2025-10-20 00:14:25.027943 | 
2025-10-20 00:14:25.028127 | TASK [add-build-sshkey : Add back temp key]
2025-10-20 00:14:25.310264 | controller -> localhost | Identity added: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/1bc2a27e9b96453c84786653f200d95b_id_ecdsa (zuul-build-sshkey)
2025-10-20 00:14:25.310475 | controller -> localhost | ok: Runtime: 0:00:00.009046
2025-10-20 00:14:25.316613 | 
2025-10-20 00:14:25.316680 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-20 00:14:25.681553 | controller | ok
2025-10-20 00:14:25.695032 | 
2025-10-20 00:14:25.695178 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-20 00:14:25.742367 | controller | skipping: Conditional result was False
2025-10-20 00:14:25.804539 | 
2025-10-20 00:14:25.804694 | TASK [include_role : remove-zuul-sshkey]
2025-10-20 00:14:25.839955 | controller | skipping: Conditional result was False
2025-10-20 00:14:25.848702 | 
2025-10-20 00:14:25.848850 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-20 00:14:26.229143 | controller | ok: "logs"
2025-10-20 00:14:26.229406 | controller | ok: All items complete
2025-10-20 00:14:26.229434 | 
2025-10-20 00:14:26.547499 | controller | ok: "artifacts"
2025-10-20 00:14:26.848380 | controller | ok: "docs"
2025-10-20 00:14:26.868665 | 
2025-10-20 00:14:26.868858 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-20 00:14:27.197165 | controller | changed: "logs"
2025-10-20 00:14:27.535360 | controller | changed: "artifacts"
2025-10-20 00:14:27.855428 | controller | changed: "docs"
2025-10-20 00:14:27.888589 | 
2025-10-20 00:14:27.888694 | PLAY RECAP
2025-10-20 00:14:27.888756 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-20 00:14:27.888789 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-20 00:14:27.888808 | 
2025-10-20 00:14:27.996479 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-20 00:14:27.997362 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-20 00:14:28.664657 | 
2025-10-20 00:14:28.664804 | PLAY [all]
2025-10-20 00:14:28.689227 | 
2025-10-20 00:14:28.689360 | TASK [Install binary dependencies]
2025-10-20 00:14:28.751050 | controller | ok
2025-10-20 00:14:28.773641 | 
2025-10-20 00:14:28.773816 | TASK [bindep : Include find tasks]
2025-10-20 00:14:28.814541 | controller | ok
2025-10-20 00:14:28.822596 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-20 00:14:28.829311 | 
2025-10-20 00:14:28.829399 | TASK [bindep : Look for bindep.txt]
2025-10-20 00:14:29.376938 | controller | ok
2025-10-20 00:14:29.393002 | 
2025-10-20 00:14:29.393220 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:29.410950 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.425986 | 
2025-10-20 00:14:29.426295 | TASK [bindep : Look for other-requirements.txt]
2025-10-20 00:14:29.760710 | controller | ok
2025-10-20 00:14:29.773347 | 
2025-10-20 00:14:29.773518 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:29.810485 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.824944 | 
2025-10-20 00:14:29.825148 | TASK [bindep : Look for bindep fallback file]
2025-10-20 00:14:29.852841 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.867268 | 
2025-10-20 00:14:29.867463 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:29.894503 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.909871 | 
2025-10-20 00:14:29.910093 | TASK [bindep : Include bindep tasks]
2025-10-20 00:14:29.938174 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.947081 | 
2025-10-20 00:14:29.947215 | TASK [bindep : Include install tasks]
2025-10-20 00:14:29.971785 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.978535 | 
2025-10-20 00:14:29.978656 | LOOP [bindep : Include package tasks]
2025-10-20 00:14:30.053672 | 
2025-10-20 00:14:30.053995 | TASK [Run test-setup role]
2025-10-20 00:14:30.078618 | controller | ok
2025-10-20 00:14:30.119433 | 
2025-10-20 00:14:30.119641 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-20 00:14:30.434865 | controller | ok
2025-10-20 00:14:30.449936 | 
2025-10-20 00:14:30.450340 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-20 00:14:30.608461 | controller | skipping: Conditional result was False
2025-10-20 00:14:30.669359 | 
2025-10-20 00:14:30.669482 | PLAY RECAP
2025-10-20 00:14:30.669535 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-20 00:14:30.669563 | 
2025-10-20 00:14:30.788248 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-20 00:14:30.789117 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-20 00:14:31.455958 | 
2025-10-20 00:14:31.456093 | PLAY [controller]
2025-10-20 00:14:31.476654 | 
2025-10-20 00:14:31.476802 | TASK [Create the /root directory]
2025-10-20 00:14:32.238875 | controller | ok
2025-10-20 00:14:32.251412 | 
2025-10-20 00:14:32.251580 | TASK [Install glibc-langpack-en]
2025-10-20 00:14:40.445407 | controller | ok: Nothing to do
2025-10-20 00:14:40.458050 | 
2025-10-20 00:14:40.458252 | TASK [Ensure controller directory exists]
2025-10-20 00:14:40.897791 | controller | changed
2025-10-20 00:14:40.910274 | 
2025-10-20 00:14:40.910449 | TASK [Install container runtime]
2025-10-20 00:14:40.978444 | controller | ok
2025-10-20 00:14:41.031543 | 
2025-10-20 00:14:41.031678 | LOOP [ensure-podman : Find distribution installation]
2025-10-20 00:14:41.054575 | controller | ok: "/var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-20 00:14:41.063523 | controller | included: /var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-20 00:14:41.070825 | 
2025-10-20 00:14:41.070902 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-20 00:16:01.171847 | controller | changed
2025-10-20 00:16:01.178599 | 
2025-10-20 00:16:01.178721 | TASK [ensure-podman : Fetch podman version]
2025-10-20 00:16:02.700360 | controller | Client:       Podman Engine
2025-10-20 00:16:02.700468 | controller | Version:      4.6.2
2025-10-20 00:16:02.700510 | controller | API Version:  4.6.2
2025-10-20 00:16:02.700559 | controller | Go Version:   go1.19.12
2025-10-20 00:16:02.700621 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-20 00:16:02.700665 | controller | OS/Arch:      linux/amd64
2025-10-20 00:16:02.836477 | controller | ok: Runtime: 0:00:00.478748
2025-10-20 00:16:02.842739 | 
2025-10-20 00:16:02.842856 | TASK [ensure-podman : Print podman version installed]
2025-10-20 00:16:02.873597 | Podman version: Client:       Podman Engine
2025-10-20 00:16:02.873772 | Version:      4.6.2
2025-10-20 00:16:02.873804 | API Version:  4.6.2
2025-10-20 00:16:02.873826 | Go Version:   go1.19.12
2025-10-20 00:16:02.873847 | Built:        Mon Aug 28 19:38:31 2023
2025-10-20 00:16:02.873869 | OS/Arch:      linux/amd64
2025-10-20 00:16:02.879533 | 
2025-10-20 00:16:02.879600 | TASK [ensure-podman : Validate podman engine]
2025-10-20 00:16:03.025823 | controller | skipping: Conditional result was False
2025-10-20 00:16:03.033657 | 
2025-10-20 00:16:03.033820 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-20 00:16:03.048105 | controller | skipping: Conditional result was False
2025-10-20 00:16:03.061474 | 
2025-10-20 00:16:03.061619 | TASK [Ensure python3.8 is present]
2025-10-20 00:16:03.081153 | controller | skipping: Conditional result was False
2025-10-20 00:16:03.096800 | 
2025-10-20 00:16:03.096994 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-20 00:16:03.127793 | controller | ok
2025-10-20 00:16:03.156495 | 
2025-10-20 00:16:03.156629 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-20 00:16:07.005778 | controller | ok: Nothing to do
2025-10-20 00:16:07.019806 | 
2025-10-20 00:16:07.020009 | TASK [our-ensure-python : Also install python3-devel]
2025-10-20 00:16:20.736577 | controller | changed
2025-10-20 00:16:20.755693 | 
2025-10-20 00:16:20.755923 | TASK [Run ensure-virtualenv role]
2025-10-20 00:16:20.781029 | controller | ok
2025-10-20 00:16:20.812916 | 
2025-10-20 00:16:20.813065 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-20 00:16:21.234367 | controller | /usr/bin/virtualenv
2025-10-20 00:16:21.443811 | controller | ok: Runtime: 0:00:00.004951
2025-10-20 00:16:21.457210 | 
2025-10-20 00:16:21.457397 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-20 00:16:21.482084 | controller | skipping: Conditional result was False
2025-10-20 00:16:21.482364 | controller | ok: All items complete
2025-10-20 00:16:21.482394 | 
2025-10-20 00:16:21.536850 | 
2025-10-20 00:16:21.537033 | TASK [Find the full path of the Python interpreter]
2025-10-20 00:16:21.994193 | controller | /usr/bin/python3
2025-10-20 00:16:22.170759 | controller | ok
2025-10-20 00:16:22.183074 | 
2025-10-20 00:16:22.183209 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-20 00:16:23.814496 | controller | created virtual environment CPython3.11.0.final.0-64 in 764ms
2025-10-20 00:16:23.859499 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-20 00:16:23.859558 | 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-20 00:16:23.859579 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-20 00:16:23.859602 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-20 00:16:24.391631 | controller | changed
2025-10-20 00:16:24.399209 | 
2025-10-20 00:16:24.399334 | TASK [Set selinux package]
2025-10-20 00:16:24.431577 | controller | ok
2025-10-20 00:16:24.438703 | 
2025-10-20 00:16:24.438852 | TASK [Set selinux package (Fedora)]
2025-10-20 00:16:24.470975 | controller | ok
2025-10-20 00:16:24.478229 | 
2025-10-20 00:16:24.478322 | TASK [Install selinux into virtualenv]
2025-10-20 00:16:27.158640 | controller | Collecting selinux-please-lie-to-me
2025-10-20 00:16:27.249670 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-20 00:16:27.781268 | controller | Collecting setuptools<50.0.0
2025-10-20 00:16:27.795199 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-20 00:16:27.896352 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.4 MB/s eta 0:00:00
2025-10-20 00:16:28.051217 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-20 00:16:28.051631 | controller |   Attempting uninstall: setuptools
2025-10-20 00:16:28.056608 | controller |     Found existing installation: setuptools 62.6.0
2025-10-20 00:16:28.169553 | controller |     Uninstalling setuptools-62.6.0:
2025-10-20 00:16:28.184857 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-20 00:16:28.961793 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-20 00:16:29.168371 | controller |
2025-10-20 00:16:29.387322 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-20 00:16:29.387366 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-20 00:16:29.666635 | controller | ok: Runtime: 0:00:04.414592
2025-10-20 00:16:29.673115 | 
2025-10-20 00:16:29.673202 | TASK [Install pytest-forked into virtualenv]
2025-10-20 00:16:30.881053 | controller | Collecting pytest-forked
2025-10-20 00:16:30.970436 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-20 00:16:31.031226 | controller | Collecting py
2025-10-20 00:16:31.045193 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-20 00:16:31.082531 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-20 00:16:31.264414 | controller | Collecting pytest>=3.10
2025-10-20 00:16:31.290188 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-20 00:16:31.365490 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.0 MB/s eta 0:00:00
2025-10-20 00:16:31.421616 | controller | Collecting iniconfig>=1
2025-10-20 00:16:31.435583 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-20 00:16:31.501818 | controller | Collecting packaging>=20
2025-10-20 00:16:31.515763 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-20 00:16:31.533544 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.1 MB/s eta 0:00:00
2025-10-20 00:16:31.581539 | controller | Collecting pluggy<2,>=1.5
2025-10-20 00:16:31.595527 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-20 00:16:31.670954 | controller | Collecting pygments>=2.7.2
2025-10-20 00:16:31.684909 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-20 00:16:31.906451 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 5.6 MB/s eta 0:00:00
2025-10-20 00:16:32.043868 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-20 00:16:34.322932 | 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-20 00:16:34.341396 | controller |
2025-10-20 00:16:34.536702 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-20 00:16:34.536767 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-20 00:16:34.827227 | controller | ok: Runtime: 0:00:04.399420
2025-10-20 00:16:34.835709 | 
2025-10-20 00:16:34.835823 | TASK [Update pip]
2025-10-20 00:16:35.950543 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-20 00:16:36.230513 | controller | Collecting pip
2025-10-20 00:16:36.333240 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-20 00:16:36.523939 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.4 MB/s eta 0:00:00
2025-10-20 00:16:36.697044 | controller | Installing collected packages: pip
2025-10-20 00:16:36.698684 | controller |   Attempting uninstall: pip
2025-10-20 00:16:36.703774 | controller |     Found existing installation: pip 22.2.2
2025-10-20 00:16:37.031727 | controller |     Uninstalling pip-22.2.2:
2025-10-20 00:16:37.076387 | controller |       Successfully uninstalled pip-22.2.2
2025-10-20 00:16:38.854492 | controller | Successfully installed pip-25.2
2025-10-20 00:16:39.494384 | controller | ok: Runtime: 0:00:03.714604
2025-10-20 00:16:39.504104 | 
2025-10-20 00:16:39.504428 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-20 00:16:40.041284 | controller | changed
2025-10-20 00:16:40.057250 | 
2025-10-20 00:16:40.057399 | TASK [Install ansible into virtualenv]
2025-10-20 00:16:41.140247 | controller | Processing ./src/github.com/ansible/ansible
2025-10-20 00:16:41.146888 | controller |   Installing build dependencies: started
2025-10-20 00:16:43.096508 | controller |   Installing build dependencies: finished with status 'done'
2025-10-20 00:16:43.097679 | controller |   Getting requirements to build wheel: started
2025-10-20 00:16:44.637656 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-20 00:16:45.579818 | controller |   Preparing metadata (pyproject.toml): started
2025-10-20 00:16:45.579874 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-20 00:16:45.583278 | 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-20 00:16:45.588183 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-20 00:16:46.225093 | controller | ERROR
2025-10-20 00:16:46.225346 | controller | {
2025-10-20 00:16:46.225378 | controller |   "delta": "0:00:05.237465",
2025-10-20 00:16:46.225398 | controller |   "end": "2025-10-20 00:16:45.743948",
2025-10-20 00:16:46.225416 | controller |   "msg": "non-zero return code",
2025-10-20 00:16:46.225450 | controller |   "rc": 1,
2025-10-20 00:16:46.225467 | controller |   "start": "2025-10-20 00:16:40.506483"
2025-10-20 00:16:46.225482 | controller | }
failure
2025-10-20 00:16:46.227340 | 
2025-10-20 00:16:46.227390 | PLAY RECAP
2025-10-20 00:16:46.227434 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-20 00:16:46.227454 | 
2025-10-20 00:16:46.385513 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-20 00:16:46.387348 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-20 00:16:47.020294 | 
2025-10-20 00:16:47.020424 | PLAY [all]
2025-10-20 00:16:47.041547 | 
2025-10-20 00:16:47.041650 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-20 00:16:47.869165 | controller | changed: non-zero return code
2025-10-20 00:16:47.885086 | 
2025-10-20 00:16:47.885336 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-20 00:16:47.903912 | controller | skipping: Conditional result was False
2025-10-20 00:16:47.920900 | 
2025-10-20 00:16:47.921135 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-20 00:16:47.961308 | 
2025-10-20 00:16:47.961570 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-20 00:16:47.990562 | 
2025-10-20 00:16:47.991290 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-20 00:16:48.030163 | controller | skipping: Conditional result was False
2025-10-20 00:16:48.036860 | 
2025-10-20 00:16:48.036990 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-20 00:16:48.071488 | 
2025-10-20 00:16:48.071715 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-20 00:16:48.098483 | controller | skipping: Conditional result was False
2025-10-20 00:16:48.109036 | 
2025-10-20 00:16:48.109188 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-20 00:16:48.124555 | controller | skipping: Conditional result was False
2025-10-20 00:16:48.133612 | 
2025-10-20 00:16:48.133756 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-20 00:16:48.149258 | controller | skipping: Conditional result was False
2025-10-20 00:16:48.188037 | 
2025-10-20 00:16:48.188153 | PLAY RECAP
2025-10-20 00:16:48.188207 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-20 00:16:48.188237 | 
2025-10-20 00:16:48.288176 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-20 00:16:48.289401 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-20 00:16:48.879421 | 
2025-10-20 00:16:48.879546 | PLAY [all:!appliance*]
2025-10-20 00:16:48.901014 | 
2025-10-20 00:16:48.901118 | TASK [unregister the node]
2025-10-20 00:16:49.033641 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.043020 | 
2025-10-20 00:16:49.043170 | TASK [include_role : fetch-output]
2025-10-20 00:16:49.087520 | controller | ok
2025-10-20 00:16:49.117136 | 
2025-10-20 00:16:49.117282 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-20 00:16:49.194345 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.203760 | 
2025-10-20 00:16:49.204001 | TASK [fetch-output : Set log path for single node]
2025-10-20 00:16:49.267907 | controller | ok
2025-10-20 00:16:49.276637 | 
2025-10-20 00:16:49.276785 | LOOP [fetch-output : Ensure local output dirs]
2025-10-20 00:16:49.716147 | controller -> localhost | ok: "/var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/logs"
2025-10-20 00:16:49.973224 | controller -> localhost | changed: "/var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/artifacts"
2025-10-20 00:16:50.197446 | controller -> localhost | changed: "/var/lib/zuul/builds/1bc2a27e9b96453c84786653f200d95b/work/docs"
2025-10-20 00:16:50.209065 | 
2025-10-20 00:16:50.209179 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-20 00:16:51.426025 | controller | changed:
2025-10-20 00:16:51.426241 | controller | .d..t...... ./
2025-10-20 00:16:51.426274 | controller | cd+++++++++ controller/
2025-10-20 00:16:51.426313 | controller | changed: All items complete
2025-10-20 00:16:51.426338 | 
2025-10-20 00:16:52.551903 | controller | changed: .d..t...... ./
2025-10-20 00:16:53.633245 | controller | changed: .d..t...... ./
2025-10-20 00:16:53.652200 | 
2025-10-20 00:16:53.652335 | TASK [include_role : fetch-output-openshift]
2025-10-20 00:16:53.674829 | controller | skipping: Conditional result was False
2025-10-20 00:16:53.683391 | 
2025-10-20 00:16:53.683525 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-20 00:16:53.715810 | controller | skipping: Conditional result was False
2025-10-20 00:16:53.725495 | controller | skipping: Conditional result was False
2025-10-20 00:16:53.758226 | 
2025-10-20 00:16:53.758317 | PLAY [localhost]
2025-10-20 00:16:53.770271 | 
2025-10-20 00:16:53.770333 | TASK [Run Zuul manifest role]
2025-10-20 00:16:53.788652 | localhost | ok
2025-10-20 00:16:53.802394 | 
2025-10-20 00:16:53.802497 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-20 00:16:54.194985 | localhost | changed
2025-10-20 00:16:54.207115 | 
2025-10-20 00:16:54.207558 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-20 00:16:54.241558 | localhost | ok
2025-10-20 00:16:54.250929 | 
2025-10-20 00:16:54.251051 | TASK [Set zuul-log-path fact]
2025-10-20 00:16:54.270874 | localhost | ok
2025-10-20 00:16:54.285319 | 
2025-10-20 00:16:54.285440 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-20 00:16:54.315844 | localhost | ok
2025-10-20 00:16:54.326315 | 
2025-10-20 00:16:54.326434 | LOOP [Run upload-logs-swift role]
2025-10-20 00:16:54.381764 | localhost | Output suppressed because no_log was given
2025-10-20 00:16:54.409463 | 
2025-10-20 00:16:54.409587 | TASK [Set zuul-log-path fact]
2025-10-20 00:16:54.433798 | localhost | skipping: Conditional result was False
2025-10-20 00:16:54.439255 | 
2025-10-20 00:16:54.439347 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-20 00:16:54.901375 | localhost -> localhost | ok: Runtime: 0:00:00.005842
2025-10-20 00:16:54.909702 | 
2025-10-20 00:16:54.909833 | TASK [upload-logs-swift : Upload logs to swift]