2025-10-26 00:12:08.479228 | Job console starting...
2025-10-26 00:12:08.487925 | Updating repositories
2025-10-26 00:12:08.653196 | Preparing job workspace
2025-10-26 00:12:12.545310 | Running Ansible setup...
2025-10-26 00:12:18.625220 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-26 00:12:19.320431 | 
2025-10-26 00:12:19.320629 | PLAY [localhost]
2025-10-26 00:12:19.330351 | 
2025-10-26 00:12:19.330424 | TASK [Gathering Facts]
2025-10-26 00:12:20.526910 | localhost | ok
2025-10-26 00:12:20.541925 | 
2025-10-26 00:12:20.542191 | TASK [Setup log path fact]
2025-10-26 00:12:20.561461 | localhost | ok
2025-10-26 00:12:20.576880 | 
2025-10-26 00:12:20.576996 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-26 00:12:20.605757 | localhost | ok
2025-10-26 00:12:20.615067 | 
2025-10-26 00:12:20.615172 | TASK [emit-job-header : Print job information]
2025-10-26 00:12:20.655213 | # Job Information
2025-10-26 00:12:20.655394 | Ansible Version: 2.15.12
2025-10-26 00:12:20.655436 | Job: ansible-test-sanity-docker-milestone
2025-10-26 00:12:20.655493 | Pipeline: periodic
2025-10-26 00:12:20.655542 | Executor: ze04.softwarefactory-project.io
2025-10-26 00:12:20.655566 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-26 00:12:20.655615 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/589/ansible/589f407e60414b20a61a4952ea975751/
2025-10-26 00:12:20.655636 | Event ID: c2e72cdc87924775bd86541f38e3bebc
2025-10-26 00:12:20.661721 | 
2025-10-26 00:12:20.661873 | LOOP [emit-job-header : Print node information]
2025-10-26 00:12:20.809141 | localhost | ok:
2025-10-26 00:12:20.809355 | localhost | # Node Information
2025-10-26 00:12:20.809386 | localhost | Inventory Hostname: controller
2025-10-26 00:12:20.809407 | localhost | Hostname: ip-172-16-242-116
2025-10-26 00:12:20.809428 | localhost | Username: zuul-worker
2025-10-26 00:12:20.809449 | localhost | Distro: Fedora 37
2025-10-26 00:12:20.809468 | localhost | Provider: ansible-us-east-2
2025-10-26 00:12:20.809486 | localhost | Region: us-east-2
2025-10-26 00:12:20.809510 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-26 00:12:20.809536 | localhost | Product Name: t3.small
2025-10-26 00:12:20.809557 | localhost | Interface IP: 18.118.167.93
2025-10-26 00:12:20.820352 | 
2025-10-26 00:12:20.820473 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-26 00:12:21.273411 | localhost -> localhost | changed
2025-10-26 00:12:21.284255 | 
2025-10-26 00:12:21.284522 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-26 00:12:22.204127 | localhost -> localhost | changed
2025-10-26 00:12:22.226271 | 
2025-10-26 00:12:22.226375 | PLAY [all:!appliance*]
2025-10-26 00:12:22.242554 | 
2025-10-26 00:12:22.242654 | TASK [include_role : start-zuul-console]
2025-10-26 00:12:22.274539 | controller | ok
2025-10-26 00:12:22.291264 | 
2025-10-26 00:12:22.291481 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-26 00:12:23.072316 | controller | ok
2025-10-26 00:12:23.100992 | 
2025-10-26 00:12:23.101166 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-26 00:12:24.904426 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-26 00:12:24.913793 | 
2025-10-26 00:12:24.913906 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-26 00:12:25.045732 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.055930 | 
2025-10-26 00:12:25.056068 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-26 00:12:25.082559 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.089513 | 
2025-10-26 00:12:25.089590 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-26 00:12:25.114428 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.120976 | 
2025-10-26 00:12:25.121055 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-26 00:12:25.156588 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.170083 | 
2025-10-26 00:12:25.170286 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-26 00:12:25.196962 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.204476 | 
2025-10-26 00:12:25.204621 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-26 00:12:25.229166 | controller | skipping: Conditional result was False
2025-10-26 00:12:25.244371 | 
2025-10-26 00:12:25.244496 | TASK [Disable Fedora Modular]
2025-10-26 00:12:25.956319 | controller | changed
2025-10-26 00:12:25.966273 | 
2025-10-26 00:12:25.966402 | TASK [Enable EPEL]
2025-10-26 00:12:25.995256 | controller | skipping: Conditional result was False
2025-10-26 00:12:26.004491 | 
2025-10-26 00:12:26.004608 | TASK [Register the RHEL node]
2025-10-26 00:12:26.157877 | 
2025-10-26 00:12:26.158065 | TASK [Show the subscription-manager status]
2025-10-26 00:12:26.402025 | controller | skipping: Conditional result was False
2025-10-26 00:12:26.409494 | 
2025-10-26 00:12:26.409589 | TASK [Enable EPEL on RHEL]
2025-10-26 00:12:26.557297 | controller | skipping: Conditional result was False
2025-10-26 00:12:26.566058 | 
2025-10-26 00:12:26.566180 | TASK [Install git and tox]
2025-10-26 00:14:13.324148 | controller | changed
2025-10-26 00:14:13.339401 | 
2025-10-26 00:14:13.339575 | TASK [include_role : prepare-workspace]
2025-10-26 00:14:13.375996 | controller | ok
2025-10-26 00:14:13.407591 | 
2025-10-26 00:14:13.407773 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-26 00:14:14.330865 | controller | ok
2025-10-26 00:14:14.349625 | 
2025-10-26 00:14:14.349874 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-26 00:14:27.216190 | controller | Output suppressed because no_log was given
2025-10-26 00:14:27.233156 | 
2025-10-26 00:14:27.233315 | TASK [include_role : prepare-workspace-openshift]
2025-10-26 00:14:27.259742 | controller | skipping: Conditional result was False
2025-10-26 00:14:27.293911 | 
2025-10-26 00:14:27.294006 | PLAY [all:!appliance]
2025-10-26 00:14:27.311673 | 
2025-10-26 00:14:27.311793 | TASK [Run add-build-sshkey role (RSA)]
2025-10-26 00:14:27.366874 | controller | ok
2025-10-26 00:14:27.382674 | 
2025-10-26 00:14:27.382799 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-26 00:14:27.671752 | controller -> localhost | ok
2025-10-26 00:14:27.681624 | 
2025-10-26 00:14:27.681789 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-26 00:14:27.706445 | controller | ok
2025-10-26 00:14:27.728812 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-26 00:14:27.737080 | 
2025-10-26 00:14:27.737162 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-26 00:14:28.294560 | controller -> localhost | Generating public/private rsa key pair.
2025-10-26 00:14:28.294751 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_rsa.
2025-10-26 00:14:28.294782 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_rsa.pub.
2025-10-26 00:14:28.294804 | controller -> localhost | The key fingerprint is:
2025-10-26 00:14:28.294824 | controller -> localhost | SHA256:fpfDX2+sdIUjTeCKQUDi4FxvLNBHqsnP0JjR8AkWsF4 zuul-build-sshkey
2025-10-26 00:14:28.294844 | controller -> localhost | The key's randomart image is:
2025-10-26 00:14:28.294864 | controller -> localhost | +---[RSA 2048]----+
2025-10-26 00:14:28.294883 | controller -> localhost | |..Booo+..   .    |
2025-10-26 00:14:28.294902 | controller -> localhost | | = X.*..   . .   |
2025-10-26 00:14:28.294921 | controller -> localhost | |. +EB.+ .   . .  |
2025-10-26 00:14:28.294940 | controller -> localhost | |...B o   o . o . |
2025-10-26 00:14:28.294958 | controller -> localhost | | .B .   S . . + .|
2025-10-26 00:14:28.294986 | controller -> localhost | |   +   .   . o ..|
2025-10-26 00:14:28.295011 | controller -> localhost | |    o   . . = ..o|
2025-10-26 00:14:28.295033 | controller -> localhost | |         . . + o+|
2025-10-26 00:14:28.295053 | controller -> localhost | |              oo.|
2025-10-26 00:14:28.295075 | controller -> localhost | +----[SHA256]-----+
2025-10-26 00:14:28.295123 | controller -> localhost | ok: Runtime: 0:00:00.148990
2025-10-26 00:14:28.302540 | 
2025-10-26 00:14:28.302641 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-26 00:14:28.328762 | controller | ok
2025-10-26 00:14:28.347037 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-26 00:14:28.359122 | 
2025-10-26 00:14:28.359235 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-26 00:14:28.374339 | controller | skipping: Conditional result was False
2025-10-26 00:14:28.382552 | 
2025-10-26 00:14:28.382673 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-26 00:14:29.023004 | controller | changed
2025-10-26 00:14:29.031713 | 
2025-10-26 00:14:29.031910 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-26 00:14:29.434563 | controller | ok
2025-10-26 00:14:29.446632 | 
2025-10-26 00:14:29.446809 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-26 00:14:30.850155 | controller | changed
2025-10-26 00:14:30.859956 | 
2025-10-26 00:14:30.860088 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-26 00:14:32.277977 | controller | changed
2025-10-26 00:14:32.291080 | 
2025-10-26 00:14:32.291226 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-26 00:14:32.328207 | controller | skipping: Conditional result was False
2025-10-26 00:14:32.341903 | 
2025-10-26 00:14:32.342064 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-26 00:14:32.708151 | controller -> localhost | changed
2025-10-26 00:14:32.727466 | 
2025-10-26 00:14:32.727608 | TASK [add-build-sshkey : Add back temp key]
2025-10-26 00:14:33.029789 | controller -> localhost | Identity added: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_rsa (zuul-build-sshkey)
2025-10-26 00:14:33.030070 | controller -> localhost | ok: Runtime: 0:00:00.007804
2025-10-26 00:14:33.037188 | 
2025-10-26 00:14:33.037304 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-26 00:14:33.719368 | controller | ok
2025-10-26 00:14:33.735893 | 
2025-10-26 00:14:33.736096 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-26 00:14:33.773607 | controller | skipping: Conditional result was False
2025-10-26 00:14:33.789883 | 
2025-10-26 00:14:33.790020 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-26 00:14:33.822237 | controller | ok
2025-10-26 00:14:33.843760 | 
2025-10-26 00:14:33.843885 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-26 00:14:34.113972 | controller -> localhost | ok
2025-10-26 00:14:34.132929 | 
2025-10-26 00:14:34.133114 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-26 00:14:34.178158 | controller | ok
2025-10-26 00:14:34.206844 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-26 00:14:34.221992 | 
2025-10-26 00:14:34.222152 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-26 00:14:34.527716 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-26 00:14:34.528118 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_ecdsa.
2025-10-26 00:14:34.528185 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_ecdsa.pub.
2025-10-26 00:14:34.528258 | controller -> localhost | The key fingerprint is:
2025-10-26 00:14:34.528328 | controller -> localhost | SHA256:sJFssX8c+F4uyqwOeZPsbQwA0JvB274Mbh8ctMPTD10 zuul-build-sshkey
2025-10-26 00:14:34.528407 | controller -> localhost | The key's randomart image is:
2025-10-26 00:14:34.528481 | controller -> localhost | +---[ECDSA 521]---+
2025-10-26 00:14:34.528530 | controller -> localhost | |.+    .          |
2025-10-26 00:14:34.528574 | controller -> localhost | |  =  . + .       |
2025-10-26 00:14:34.528614 | controller -> localhost | |   B. B . E      |
2025-10-26 00:14:34.528654 | controller -> localhost | |  +oo+ * + .     |
2025-10-26 00:14:34.528741 | controller -> localhost | |   .*.+ S + .    |
2025-10-26 00:14:34.528787 | controller -> localhost | |  ...*.+ o o     |
2025-10-26 00:14:34.528826 | controller -> localhost | | . o=.=o. o .    |
2025-10-26 00:14:34.528865 | controller -> localhost | |  o o= =o. .     |
2025-10-26 00:14:34.528903 | controller -> localhost | | . ...+o=        |
2025-10-26 00:14:34.528951 | controller -> localhost | +----[SHA256]-----+
2025-10-26 00:14:34.529055 | controller -> localhost | ok: Runtime: 0:00:00.010249
2025-10-26 00:14:34.549204 | 
2025-10-26 00:14:34.549358 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-26 00:14:34.593535 | controller | ok
2025-10-26 00:14:34.605877 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-26 00:14:34.619668 | 
2025-10-26 00:14:34.619791 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-26 00:14:34.655398 | controller | skipping: Conditional result was False
2025-10-26 00:14:34.665938 | 
2025-10-26 00:14:34.666041 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-26 00:14:35.398404 | controller | changed
2025-10-26 00:14:35.414286 | 
2025-10-26 00:14:35.414507 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-26 00:14:35.874276 | controller | ok
2025-10-26 00:14:35.886988 | 
2025-10-26 00:14:35.887142 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-26 00:14:37.501641 | controller | changed
2025-10-26 00:14:37.514857 | 
2025-10-26 00:14:37.514997 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-26 00:14:38.943998 | controller | changed
2025-10-26 00:14:38.951703 | 
2025-10-26 00:14:38.951795 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-26 00:14:38.975892 | controller | skipping: Conditional result was False
2025-10-26 00:14:38.983307 | 
2025-10-26 00:14:38.983413 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-26 00:14:39.221084 | controller -> localhost | changed
2025-10-26 00:14:39.269987 | 
2025-10-26 00:14:39.270140 | TASK [add-build-sshkey : Add back temp key]
2025-10-26 00:14:39.563082 | controller -> localhost | Identity added: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/589f407e60414b20a61a4952ea975751_id_ecdsa (zuul-build-sshkey)
2025-10-26 00:14:39.563435 | controller -> localhost | ok: Runtime: 0:00:00.009881
2025-10-26 00:14:39.579624 | 
2025-10-26 00:14:39.579823 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-26 00:14:39.986662 | controller | ok
2025-10-26 00:14:39.995359 | 
2025-10-26 00:14:39.995464 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-26 00:14:40.041847 | controller | skipping: Conditional result was False
2025-10-26 00:14:40.095879 | 
2025-10-26 00:14:40.096017 | TASK [include_role : remove-zuul-sshkey]
2025-10-26 00:14:40.120977 | controller | skipping: Conditional result was False
2025-10-26 00:14:40.127500 | 
2025-10-26 00:14:40.127589 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-26 00:14:40.465215 | controller | ok: "logs"
2025-10-26 00:14:40.465791 | controller | ok: All items complete
2025-10-26 00:14:40.465923 | 
2025-10-26 00:14:40.766270 | controller | ok: "artifacts"
2025-10-26 00:14:41.073407 | controller | ok: "docs"
2025-10-26 00:14:41.094074 | 
2025-10-26 00:14:41.094230 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-26 00:14:41.504895 | controller | changed: "logs"
2025-10-26 00:14:41.837206 | controller | changed: "artifacts"
2025-10-26 00:14:42.181657 | controller | changed: "docs"
2025-10-26 00:14:42.244179 | 
2025-10-26 00:14:42.244407 | PLAY RECAP
2025-10-26 00:14:42.244475 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-26 00:14:42.244516 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-26 00:14:42.244546 | 
2025-10-26 00:14:42.385052 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-26 00:14:42.386269 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-26 00:14:43.031445 | 
2025-10-26 00:14:43.031606 | PLAY [all]
2025-10-26 00:14:43.064196 | 
2025-10-26 00:14:43.064365 | TASK [Install binary dependencies]
2025-10-26 00:14:43.129330 | controller | ok
2025-10-26 00:14:43.150200 | 
2025-10-26 00:14:43.150345 | TASK [bindep : Include find tasks]
2025-10-26 00:14:43.179930 | controller | ok
2025-10-26 00:14:43.188702 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-26 00:14:43.195875 | 
2025-10-26 00:14:43.195991 | TASK [bindep : Look for bindep.txt]
2025-10-26 00:14:43.720399 | controller | ok
2025-10-26 00:14:43.730125 | 
2025-10-26 00:14:43.730273 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:14:43.756471 | controller | skipping: Conditional result was False
2025-10-26 00:14:43.766382 | 
2025-10-26 00:14:43.766512 | TASK [bindep : Look for other-requirements.txt]
2025-10-26 00:14:44.129446 | controller | ok
2025-10-26 00:14:44.141564 | 
2025-10-26 00:14:44.141785 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:14:44.191207 | controller | skipping: Conditional result was False
2025-10-26 00:14:44.211258 | 
2025-10-26 00:14:44.211507 | TASK [bindep : Look for bindep fallback file]
2025-10-26 00:14:44.241387 | controller | skipping: Conditional result was False
2025-10-26 00:14:44.251365 | 
2025-10-26 00:14:44.251485 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:14:44.277034 | controller | skipping: Conditional result was False
2025-10-26 00:14:44.286751 | 
2025-10-26 00:14:44.286900 | TASK [bindep : Include bindep tasks]
2025-10-26 00:14:44.312670 | controller | skipping: Conditional result was False
2025-10-26 00:14:44.323055 | 
2025-10-26 00:14:44.323171 | TASK [bindep : Include install tasks]
2025-10-26 00:14:44.358099 | controller | skipping: Conditional result was False
2025-10-26 00:14:44.366707 | 
2025-10-26 00:14:44.366824 | LOOP [bindep : Include package tasks]
2025-10-26 00:14:44.426872 | 
2025-10-26 00:14:44.427072 | TASK [Run test-setup role]
2025-10-26 00:14:44.449937 | controller | ok
2025-10-26 00:14:44.476343 | 
2025-10-26 00:14:44.476485 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-26 00:14:44.918949 | controller | ok
2025-10-26 00:14:44.925732 | 
2025-10-26 00:14:44.925803 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-26 00:14:45.062256 | controller | skipping: Conditional result was False
2025-10-26 00:14:45.088819 | 
2025-10-26 00:14:45.088917 | PLAY RECAP
2025-10-26 00:14:45.088961 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-26 00:14:45.088984 | 
2025-10-26 00:14:45.209548 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-26 00:14:45.210802 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-26 00:14:45.879965 | 
2025-10-26 00:14:45.880090 | PLAY [controller]
2025-10-26 00:14:45.902827 | 
2025-10-26 00:14:45.902970 | TASK [Create the /root directory]
2025-10-26 00:14:46.666039 | controller | ok
2025-10-26 00:14:46.679285 | 
2025-10-26 00:14:46.679443 | TASK [Install glibc-langpack-en]
2025-10-26 00:14:54.866326 | controller | ok: Nothing to do
2025-10-26 00:14:54.873157 | 
2025-10-26 00:14:54.873251 | TASK [Ensure controller directory exists]
2025-10-26 00:14:55.300878 | controller | changed
2025-10-26 00:14:55.313789 | 
2025-10-26 00:14:55.313978 | TASK [Install container runtime]
2025-10-26 00:14:55.397559 | controller | ok
2025-10-26 00:14:55.446208 | 
2025-10-26 00:14:55.446363 | LOOP [ensure-podman : Find distribution installation]
2025-10-26 00:14:55.492607 | controller | ok: "/var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-26 00:14:55.517198 | controller | included: /var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-26 00:14:55.531006 | 
2025-10-26 00:14:55.531100 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-26 00:16:21.474556 | controller | changed
2025-10-26 00:16:21.490184 | 
2025-10-26 00:16:21.490365 | TASK [ensure-podman : Fetch podman version]
2025-10-26 00:16:22.242660 | controller | Client:       Podman Engine
2025-10-26 00:16:22.242831 | controller | Version:      4.6.2
2025-10-26 00:16:22.243017 | controller | API Version:  4.6.2
2025-10-26 00:16:22.243052 | controller | Go Version:   go1.19.12
2025-10-26 00:16:22.243094 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-26 00:16:22.243124 | controller | OS/Arch:      linux/amd64
2025-10-26 00:16:22.644270 | controller | ok: Runtime: 0:00:00.258302
2025-10-26 00:16:22.653723 | 
2025-10-26 00:16:22.653855 | TASK [ensure-podman : Print podman version installed]
2025-10-26 00:16:22.686892 | Podman version: Client:       Podman Engine
2025-10-26 00:16:22.687157 | Version:      4.6.2
2025-10-26 00:16:22.687247 | API Version:  4.6.2
2025-10-26 00:16:22.687295 | Go Version:   go1.19.12
2025-10-26 00:16:22.687336 | Built:        Mon Aug 28 19:38:31 2023
2025-10-26 00:16:22.687379 | OS/Arch:      linux/amd64
2025-10-26 00:16:22.699627 | 
2025-10-26 00:16:22.699924 | TASK [ensure-podman : Validate podman engine]
2025-10-26 00:16:22.839757 | controller | skipping: Conditional result was False
2025-10-26 00:16:22.847055 | 
2025-10-26 00:16:22.847145 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-26 00:16:22.861584 | controller | skipping: Conditional result was False
2025-10-26 00:16:22.874201 | 
2025-10-26 00:16:22.874433 | TASK [Ensure python3.8 is present]
2025-10-26 00:16:22.889088 | controller | skipping: Conditional result was False
2025-10-26 00:16:22.896516 | 
2025-10-26 00:16:22.896618 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-26 00:16:22.917781 | controller | ok
2025-10-26 00:16:22.938393 | 
2025-10-26 00:16:22.938515 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-26 00:16:26.694859 | controller | ok: Nothing to do
2025-10-26 00:16:26.704329 | 
2025-10-26 00:16:26.704484 | TASK [our-ensure-python : Also install python3-devel]
2025-10-26 00:16:40.594629 | controller | changed
2025-10-26 00:16:40.604842 | 
2025-10-26 00:16:40.604904 | TASK [Run ensure-virtualenv role]
2025-10-26 00:16:40.624649 | controller | ok
2025-10-26 00:16:40.644424 | 
2025-10-26 00:16:40.644491 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-26 00:16:41.051069 | controller | /usr/bin/virtualenv
2025-10-26 00:16:41.283007 | controller | ok: Runtime: 0:00:00.004670
2025-10-26 00:16:41.296559 | 
2025-10-26 00:16:41.296764 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-26 00:16:41.333108 | controller | skipping: Conditional result was False
2025-10-26 00:16:41.333414 | controller | ok: All items complete
2025-10-26 00:16:41.333448 | 
2025-10-26 00:16:41.348998 | 
2025-10-26 00:16:41.349151 | TASK [Find the full path of the Python interpreter]
2025-10-26 00:16:41.837154 | controller | /usr/bin/python3
2025-10-26 00:16:42.021745 | controller | ok
2025-10-26 00:16:42.033714 | 
2025-10-26 00:16:42.033857 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-26 00:16:43.554484 | controller | created virtual environment CPython3.11.0.final.0-64 in 765ms
2025-10-26 00:16:43.598315 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-26 00:16:43.598417 | 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-26 00:16:43.598434 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-26 00:16:43.598457 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-26 00:16:43.704065 | controller | changed
2025-10-26 00:16:43.717184 | 
2025-10-26 00:16:43.717330 | TASK [Set selinux package]
2025-10-26 00:16:43.757496 | controller | ok
2025-10-26 00:16:43.770422 | 
2025-10-26 00:16:43.770575 | TASK [Set selinux package (Fedora)]
2025-10-26 00:16:43.830555 | controller | ok
2025-10-26 00:16:43.842586 | 
2025-10-26 00:16:43.842763 | TASK [Install selinux into virtualenv]
2025-10-26 00:16:46.498546 | controller | Collecting selinux-please-lie-to-me
2025-10-26 00:16:46.591170 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-26 00:16:47.125272 | controller | Collecting setuptools<50.0.0
2025-10-26 00:16:47.138903 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-26 00:16:47.261941 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-10-26 00:16:47.412949 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-26 00:16:47.413252 | controller |   Attempting uninstall: setuptools
2025-10-26 00:16:47.418109 | controller |     Found existing installation: setuptools 62.6.0
2025-10-26 00:16:47.530274 | controller |     Uninstalling setuptools-62.6.0:
2025-10-26 00:16:47.545718 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-26 00:16:48.303770 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-26 00:16:48.510026 | controller |
2025-10-26 00:16:48.725072 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-26 00:16:48.725126 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-26 00:16:48.999912 | controller | ok: Runtime: 0:00:04.402662
2025-10-26 00:16:49.014898 | 
2025-10-26 00:16:49.015052 | TASK [Install pytest-forked into virtualenv]
2025-10-26 00:16:50.233691 | controller | Collecting pytest-forked
2025-10-26 00:16:50.322760 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-26 00:16:50.383404 | controller | Collecting py
2025-10-26 00:16:50.395898 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-26 00:16:50.433415 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-10-26 00:16:50.611918 | controller | Collecting pytest>=3.10
2025-10-26 00:16:50.624107 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-26 00:16:50.687163 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.1 MB/s eta 0:00:00
2025-10-26 00:16:50.744393 | controller | Collecting iniconfig>=1
2025-10-26 00:16:50.756949 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-26 00:16:50.823958 | controller | Collecting packaging>=20
2025-10-26 00:16:50.835997 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-26 00:16:50.847921 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.0 MB/s eta 0:00:00
2025-10-26 00:16:50.897189 | controller | Collecting pluggy<2,>=1.5
2025-10-26 00:16:50.909237 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-26 00:16:50.984080 | controller | Collecting pygments>=2.7.2
2025-10-26 00:16:50.995953 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-26 00:16:51.113327 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-10-26 00:16:51.246241 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-26 00:16:53.507484 | 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-26 00:16:53.524056 | controller |
2025-10-26 00:16:53.716535 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-26 00:16:53.716589 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-26 00:16:54.200577 | controller | ok: Runtime: 0:00:04.212364
2025-10-26 00:16:54.213158 | 
2025-10-26 00:16:54.213310 | TASK [Update pip]
2025-10-26 00:16:55.371823 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-26 00:16:55.637133 | controller | Collecting pip
2025-10-26 00:16:55.735728 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-26 00:16:55.902092 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.0 MB/s eta 0:00:00
2025-10-26 00:16:56.065086 | controller | Installing collected packages: pip
2025-10-26 00:16:56.066529 | controller |   Attempting uninstall: pip
2025-10-26 00:16:56.071561 | controller |     Found existing installation: pip 22.2.2
2025-10-26 00:16:56.395102 | controller |     Uninstalling pip-22.2.2:
2025-10-26 00:16:56.434227 | controller |       Successfully uninstalled pip-22.2.2
2025-10-26 00:16:58.201386 | controller | Successfully installed pip-25.3
2025-10-26 00:16:58.884829 | controller | ok: Runtime: 0:00:03.666720
2025-10-26 00:16:58.890301 | 
2025-10-26 00:16:58.890363 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-26 00:16:59.461090 | controller | changed
2025-10-26 00:16:59.470022 | 
2025-10-26 00:16:59.470506 | TASK [Install ansible into virtualenv]
2025-10-26 00:17:00.643767 | controller | Processing ./src/github.com/ansible/ansible
2025-10-26 00:17:00.654225 | controller |   Installing build dependencies: started
2025-10-26 00:17:02.926776 | controller |   Installing build dependencies: finished with status 'done'
2025-10-26 00:17:04.535241 | controller |   Getting requirements to build wheel: started
2025-10-26 00:17:04.535305 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-26 00:17:04.536638 | controller |   Preparing metadata (pyproject.toml): started
2025-10-26 00:17:05.466677 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-26 00:17:05.471162 | 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-26 00:17:05.471215 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-26 00:17:06.130170 | controller | ERROR
2025-10-26 00:17:06.130385 | controller | {
2025-10-26 00:17:06.130415 | controller |   "delta": "0:00:05.683280",
2025-10-26 00:17:06.130436 | controller |   "end": "2025-10-26 00:17:05.617275",
2025-10-26 00:17:06.130455 | controller |   "msg": "non-zero return code",
2025-10-26 00:17:06.130484 | controller |   "rc": 1,
2025-10-26 00:17:06.130501 | controller |   "start": "2025-10-26 00:16:59.933995"
2025-10-26 00:17:06.130516 | controller | }
failure
2025-10-26 00:17:06.132448 | 
2025-10-26 00:17:06.132498 | PLAY RECAP
2025-10-26 00:17:06.132548 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-26 00:17:06.132575 | 
2025-10-26 00:17:06.275486 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-26 00:17:06.276540 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-26 00:17:06.856190 | 
2025-10-26 00:17:06.856320 | PLAY [all]
2025-10-26 00:17:06.881317 | 
2025-10-26 00:17:06.881456 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-26 00:17:07.627184 | controller | changed: non-zero return code
2025-10-26 00:17:07.635666 | 
2025-10-26 00:17:07.635825 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-26 00:17:07.661552 | controller | skipping: Conditional result was False
2025-10-26 00:17:07.667661 | 
2025-10-26 00:17:07.667770 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-26 00:17:07.694151 | 
2025-10-26 00:17:07.694411 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-26 00:17:07.717104 | 
2025-10-26 00:17:07.717352 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-26 00:17:07.733930 | controller | skipping: Conditional result was False
2025-10-26 00:17:07.741260 | 
2025-10-26 00:17:07.741404 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-26 00:17:07.765604 | 
2025-10-26 00:17:07.765948 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-26 00:17:07.782244 | controller | skipping: Conditional result was False
2025-10-26 00:17:07.789604 | 
2025-10-26 00:17:07.789752 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-26 00:17:07.826103 | controller | skipping: Conditional result was False
2025-10-26 00:17:07.832637 | 
2025-10-26 00:17:07.832762 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-26 00:17:07.866674 | controller | skipping: Conditional result was False
2025-10-26 00:17:07.892069 | 
2025-10-26 00:17:07.892171 | PLAY RECAP
2025-10-26 00:17:07.892213 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-26 00:17:07.892233 | 
2025-10-26 00:17:07.994896 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-26 00:17:07.996046 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-26 00:17:08.586085 | 
2025-10-26 00:17:08.586206 | PLAY [all:!appliance*]
2025-10-26 00:17:08.609317 | 
2025-10-26 00:17:08.609418 | TASK [unregister the node]
2025-10-26 00:17:08.760935 | controller | skipping: Conditional result was False
2025-10-26 00:17:08.776058 | 
2025-10-26 00:17:08.776275 | TASK [include_role : fetch-output]
2025-10-26 00:17:08.835578 | controller | ok
2025-10-26 00:17:08.872970 | 
2025-10-26 00:17:08.873112 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-26 00:17:08.950285 | controller | skipping: Conditional result was False
2025-10-26 00:17:08.962870 | 
2025-10-26 00:17:08.963029 | TASK [fetch-output : Set log path for single node]
2025-10-26 00:17:09.032156 | controller | ok
2025-10-26 00:17:09.044147 | 
2025-10-26 00:17:09.044304 | LOOP [fetch-output : Ensure local output dirs]
2025-10-26 00:17:09.540234 | controller -> localhost | ok: "/var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/logs"
2025-10-26 00:17:09.811773 | controller -> localhost | changed: "/var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/artifacts"
2025-10-26 00:17:10.106427 | controller -> localhost | changed: "/var/lib/zuul/builds/589f407e60414b20a61a4952ea975751/work/docs"
2025-10-26 00:17:10.126151 | 
2025-10-26 00:17:10.126277 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-26 00:17:11.420997 | controller | changed:
2025-10-26 00:17:11.421525 | controller | .d..t...... ./
2025-10-26 00:17:11.421598 | controller | cd+++++++++ controller/
2025-10-26 00:17:11.421665 | controller | changed: All items complete
2025-10-26 00:17:11.421755 | 
2025-10-26 00:17:12.474606 | controller | changed: .d..t...... ./
2025-10-26 00:17:13.552860 | controller | changed: .d..t...... ./
2025-10-26 00:17:13.589139 | 
2025-10-26 00:17:13.589310 | TASK [include_role : fetch-output-openshift]
2025-10-26 00:17:13.616232 | controller | skipping: Conditional result was False
2025-10-26 00:17:13.629756 | 
2025-10-26 00:17:13.629914 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-26 00:17:13.677191 | controller | skipping: Conditional result was False
2025-10-26 00:17:13.688617 | controller | skipping: Conditional result was False
2025-10-26 00:17:13.742004 | 
2025-10-26 00:17:13.742144 | PLAY [localhost]
2025-10-26 00:17:13.759495 | 
2025-10-26 00:17:13.759588 | TASK [Run Zuul manifest role]
2025-10-26 00:17:13.781050 | localhost | ok
2025-10-26 00:17:13.800776 | 
2025-10-26 00:17:13.800897 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-26 00:17:14.250924 | localhost | changed
2025-10-26 00:17:14.258091 | 
2025-10-26 00:17:14.258208 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-26 00:17:14.290774 | localhost | ok
2025-10-26 00:17:14.302828 | 
2025-10-26 00:17:14.302954 | TASK [Set zuul-log-path fact]
2025-10-26 00:17:14.324760 | localhost | ok
2025-10-26 00:17:14.344897 | 
2025-10-26 00:17:14.345021 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-26 00:17:14.374044 | localhost | ok
2025-10-26 00:17:14.384206 | 
2025-10-26 00:17:14.384315 | LOOP [Run upload-logs-swift role]
2025-10-26 00:17:14.419558 | localhost | Output suppressed because no_log was given
2025-10-26 00:17:14.461019 | 
2025-10-26 00:17:14.461138 | TASK [Set zuul-log-path fact]
2025-10-26 00:17:14.486810 | localhost | skipping: Conditional result was False
2025-10-26 00:17:14.492501 | 
2025-10-26 00:17:14.492579 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-26 00:17:14.935195 | localhost -> localhost | ok: Runtime: 0:00:00.008566
2025-10-26 00:17:14.941610 | 
2025-10-26 00:17:14.941743 | TASK [upload-logs-swift : Upload logs to swift]