2025-11-24 00:21:00.003576 | Job console starting...
2025-11-24 00:21:00.016101 | Updating repositories
2025-11-24 00:21:00.148922 | Preparing job workspace
2025-11-24 00:21:04.374594 | Running Ansible setup...
2025-11-24 00:21:08.662991 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-24 00:21:09.251561 | 
2025-11-24 00:21:09.251696 | PLAY [localhost]
2025-11-24 00:21:09.271386 | 
2025-11-24 00:21:09.271479 | TASK [Gathering Facts]
2025-11-24 00:21:10.276126 | localhost | ok
2025-11-24 00:21:10.293318 | 
2025-11-24 00:21:10.293452 | TASK [Setup log path fact]
2025-11-24 00:21:10.314220 | localhost | ok
2025-11-24 00:21:10.339891 | 
2025-11-24 00:21:10.340023 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-24 00:21:10.368705 | localhost | ok
2025-11-24 00:21:10.376942 | 
2025-11-24 00:21:10.377020 | TASK [emit-job-header : Print job information]
2025-11-24 00:21:10.417280 | # Job Information
2025-11-24 00:21:10.417467 | Ansible Version: 2.15.12
2025-11-24 00:21:10.417511 | Job: ansible-test-sanity-docker-milestone
2025-11-24 00:21:10.417541 | Pipeline: periodic
2025-11-24 00:21:10.417568 | Executor: ze04.softwarefactory-project.io
2025-11-24 00:21:10.417593 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-24 00:21:10.417623 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/76a/ansible/76a7a07671de46e19dbe219872fa0e9c/
2025-11-24 00:21:10.417650 | Event ID: db80f5515f954e34b34bdcccc30c1493
2025-11-24 00:21:10.424335 | 
2025-11-24 00:21:10.424473 | LOOP [emit-job-header : Print node information]
2025-11-24 00:21:10.547117 | localhost | ok:
2025-11-24 00:21:10.547256 | localhost | # Node Information
2025-11-24 00:21:10.547283 | localhost | Inventory Hostname: controller
2025-11-24 00:21:10.547303 | localhost | Hostname: np0005532876
2025-11-24 00:21:10.547322 | localhost | Username: zuul
2025-11-24 00:21:10.547343 | localhost | Distro: Fedora 37
2025-11-24 00:21:10.547361 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-24 00:21:10.547379 | localhost | Region: ca-ymq-1
2025-11-24 00:21:10.547397 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-24 00:21:10.547413 | localhost | Product Name: OpenStack Nova
2025-11-24 00:21:10.547430 | localhost | Interface IP: 162.253.55.84
2025-11-24 00:21:10.557820 | 
2025-11-24 00:21:10.557934 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-24 00:21:10.969162 | localhost -> localhost | changed
2025-11-24 00:21:10.974525 | 
2025-11-24 00:21:10.974588 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-24 00:21:12.018984 | localhost -> localhost | changed
2025-11-24 00:21:12.039814 | 
2025-11-24 00:21:12.039898 | PLAY [all:!appliance*]
2025-11-24 00:21:12.056966 | 
2025-11-24 00:21:12.057081 | TASK [include_role : start-zuul-console]
2025-11-24 00:21:12.078157 | controller | ok
2025-11-24 00:21:12.092763 | 
2025-11-24 00:21:12.092870 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-24 00:21:12.503960 | controller | ok
2025-11-24 00:21:12.521280 | 
2025-11-24 00:21:12.521358 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-24 00:21:13.559342 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-24 00:21:13.573021 | 
2025-11-24 00:21:13.573165 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-24 00:21:14.123791 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.137919 | 
2025-11-24 00:21:14.138098 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-24 00:21:14.165984 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.173671 | 
2025-11-24 00:21:14.173809 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-24 00:21:14.199001 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.214094 | 
2025-11-24 00:21:14.214261 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-24 00:21:14.251884 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.267666 | 
2025-11-24 00:21:14.267936 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-24 00:21:14.305079 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.319478 | 
2025-11-24 00:21:14.319657 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-24 00:21:14.349174 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.377074 | 
2025-11-24 00:21:14.377253 | TASK [Disable Fedora Modular]
2025-11-24 00:21:14.614322 | controller | changed
2025-11-24 00:21:14.622167 | 
2025-11-24 00:21:14.622254 | TASK [Enable EPEL]
2025-11-24 00:21:14.647565 | controller | skipping: Conditional result was False
2025-11-24 00:21:14.656760 | 
2025-11-24 00:21:14.656911 | TASK [Register the RHEL node]
2025-11-24 00:21:15.216329 | 
2025-11-24 00:21:15.216522 | TASK [Show the subscription-manager status]
2025-11-24 00:21:15.792606 | controller | skipping: Conditional result was False
2025-11-24 00:21:15.804500 | 
2025-11-24 00:21:15.804674 | TASK [Enable EPEL on RHEL]
2025-11-24 00:21:16.344645 | controller | skipping: Conditional result was False
2025-11-24 00:21:16.352926 | 
2025-11-24 00:21:16.353019 | TASK [Install git and tox]
2025-11-24 00:22:43.347935 | controller | changed
2025-11-24 00:22:43.362922 | 
2025-11-24 00:22:43.363088 | TASK [include_role : prepare-workspace]
2025-11-24 00:22:43.402319 | controller | ok
2025-11-24 00:22:43.443938 | 
2025-11-24 00:22:43.444087 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-24 00:22:43.696145 | controller | ok
2025-11-24 00:22:43.714390 | 
2025-11-24 00:22:43.714596 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-24 00:22:56.042385 | controller | Output suppressed because no_log was given
2025-11-24 00:22:56.084178 | 
2025-11-24 00:22:56.084301 | TASK [include_role : prepare-workspace-openshift]
2025-11-24 00:22:56.108738 | controller | skipping: Conditional result was False
2025-11-24 00:22:56.137464 | 
2025-11-24 00:22:56.137520 | PLAY [all:!appliance]
2025-11-24 00:22:56.153671 | 
2025-11-24 00:22:56.153767 | TASK [Run add-build-sshkey role (RSA)]
2025-11-24 00:22:56.196402 | controller | ok
2025-11-24 00:22:56.217596 | 
2025-11-24 00:22:56.217763 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-24 00:22:56.499392 | controller -> localhost | ok
2025-11-24 00:22:56.505954 | 
2025-11-24 00:22:56.506021 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-24 00:22:56.546580 | controller | ok
2025-11-24 00:22:56.559657 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-24 00:22:56.565418 | 
2025-11-24 00:22:56.565478 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-24 00:22:57.120659 | controller -> localhost | Generating public/private rsa key pair.
2025-11-24 00:22:57.121062 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_rsa.
2025-11-24 00:22:57.121129 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_rsa.pub.
2025-11-24 00:22:57.121177 | controller -> localhost | The key fingerprint is:
2025-11-24 00:22:57.121222 | controller -> localhost | SHA256:DnU0C8r2SJ7pOPbXnMoiAV3PDMaLx+xfmz9thCCWtJ8 zuul-build-sshkey
2025-11-24 00:22:57.121265 | controller -> localhost | The key's randomart image is:
2025-11-24 00:22:57.121307 | controller -> localhost | +---[RSA 2048]----+
2025-11-24 00:22:57.121348 | controller -> localhost | |     .  . o      |
2025-11-24 00:22:57.121394 | controller -> localhost | |     .=..o o     |
2025-11-24 00:22:57.121434 | controller -> localhost | |   . *=B.oo      |
2025-11-24 00:22:57.121474 | controller -> localhost | |  . o+=*O..      |
2025-11-24 00:22:57.121514 | controller -> localhost | |   . o*.So o .   |
2025-11-24 00:22:57.121570 | controller -> localhost | |    .o.o  E . .  |
2025-11-24 00:22:57.121618 | controller -> localhost | |    +....+ + o   |
2025-11-24 00:22:57.121666 | controller -> localhost | |   ..o..o * . o  |
2025-11-24 00:22:57.121773 | controller -> localhost | |     ..oo. ..o   |
2025-11-24 00:22:57.121826 | controller -> localhost | +----[SHA256]-----+
2025-11-24 00:22:57.121922 | controller -> localhost | ok: Runtime: 0:00:00.112172
2025-11-24 00:22:57.136485 | 
2025-11-24 00:22:57.136624 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-24 00:22:57.160565 | controller | ok
2025-11-24 00:22:57.173506 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-24 00:22:57.185192 | 
2025-11-24 00:22:57.185276 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-24 00:22:57.200596 | controller | skipping: Conditional result was False
2025-11-24 00:22:57.209831 | 
2025-11-24 00:22:57.209917 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-24 00:22:57.635901 | controller | changed
2025-11-24 00:22:57.651201 | 
2025-11-24 00:22:57.651345 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-24 00:22:57.887391 | controller | ok
2025-11-24 00:22:57.899555 | 
2025-11-24 00:22:57.899940 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-24 00:22:58.555277 | controller | changed
2025-11-24 00:22:58.571112 | 
2025-11-24 00:22:58.571269 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-24 00:22:59.234584 | controller | changed
2025-11-24 00:22:59.247424 | 
2025-11-24 00:22:59.247584 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-24 00:22:59.266070 | controller | skipping: Conditional result was False
2025-11-24 00:22:59.280287 | 
2025-11-24 00:22:59.280425 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-24 00:22:59.685733 | controller -> localhost | changed
2025-11-24 00:22:59.697369 | 
2025-11-24 00:22:59.697470 | TASK [add-build-sshkey : Add back temp key]
2025-11-24 00:22:59.976427 | controller -> localhost | Identity added: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_rsa (zuul-build-sshkey)
2025-11-24 00:22:59.976812 | controller -> localhost | ok: Runtime: 0:00:00.013583
2025-11-24 00:22:59.991991 | 
2025-11-24 00:22:59.992210 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-24 00:23:00.369581 | controller | ok
2025-11-24 00:23:00.381515 | 
2025-11-24 00:23:00.381646 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-24 00:23:00.420942 | controller | skipping: Conditional result was False
2025-11-24 00:23:00.436390 | 
2025-11-24 00:23:00.436488 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-24 00:23:00.478387 | controller | ok
2025-11-24 00:23:00.502891 | 
2025-11-24 00:23:00.502983 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-24 00:23:00.794272 | controller -> localhost | ok
2025-11-24 00:23:00.810652 | 
2025-11-24 00:23:00.810862 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-24 00:23:00.851966 | controller | ok
2025-11-24 00:23:00.876216 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-24 00:23:00.887360 | 
2025-11-24 00:23:00.887489 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-24 00:23:01.168262 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-24 00:23:01.168485 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_ecdsa.
2025-11-24 00:23:01.168519 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_ecdsa.pub.
2025-11-24 00:23:01.168557 | controller -> localhost | The key fingerprint is:
2025-11-24 00:23:01.168585 | controller -> localhost | SHA256:f51+cW20B1/9s5enrYl/PDyAL2+HYhfoMXMlVserJZA zuul-build-sshkey
2025-11-24 00:23:01.168610 | controller -> localhost | The key's randomart image is:
2025-11-24 00:23:01.168634 | controller -> localhost | +---[ECDSA 521]---+
2025-11-24 00:23:01.168656 | controller -> localhost | |            .  . |
2025-11-24 00:23:01.168790 | controller -> localhost | |           E   .o|
2025-11-24 00:23:01.168833 | controller -> localhost | |            . . +|
2025-11-24 00:23:01.168859 | controller -> localhost | |             +.++|
2025-11-24 00:23:01.168882 | controller -> localhost | |        S   + *+=|
2025-11-24 00:23:01.168904 | controller -> localhost | |         . * * =B|
2025-11-24 00:23:01.168929 | controller -> localhost | |          o B BoB|
2025-11-24 00:23:01.168955 | controller -> localhost | |           * B X*|
2025-11-24 00:23:01.168978 | controller -> localhost | |          . BoB=*|
2025-11-24 00:23:01.169000 | controller -> localhost | +----[SHA256]-----+
2025-11-24 00:23:01.169060 | controller -> localhost | ok: Runtime: 0:00:00.009732
2025-11-24 00:23:01.178072 | 
2025-11-24 00:23:01.178154 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-24 00:23:01.211831 | controller | ok
2025-11-24 00:23:01.222133 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-24 00:23:01.235138 | 
2025-11-24 00:23:01.235243 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-24 00:23:01.261498 | controller | skipping: Conditional result was False
2025-11-24 00:23:01.271532 | 
2025-11-24 00:23:01.271628 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-24 00:23:01.539323 | controller | changed
2025-11-24 00:23:01.547451 | 
2025-11-24 00:23:01.547533 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-24 00:23:01.790132 | controller | ok
2025-11-24 00:23:01.803928 | 
2025-11-24 00:23:01.804114 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-24 00:23:02.447109 | controller | changed
2025-11-24 00:23:02.455639 | 
2025-11-24 00:23:02.455768 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-24 00:23:03.084843 | controller | changed
2025-11-24 00:23:03.098490 | 
2025-11-24 00:23:03.098651 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-24 00:23:03.118241 | controller | skipping: Conditional result was False
2025-11-24 00:23:03.135455 | 
2025-11-24 00:23:03.135647 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-24 00:23:03.412751 | controller -> localhost | changed
2025-11-24 00:23:03.456576 | 
2025-11-24 00:23:03.456708 | TASK [add-build-sshkey : Add back temp key]
2025-11-24 00:23:03.806939 | controller -> localhost | Identity added: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/76a7a07671de46e19dbe219872fa0e9c_id_ecdsa (zuul-build-sshkey)
2025-11-24 00:23:03.807186 | controller -> localhost | ok: Runtime: 0:00:00.007385
2025-11-24 00:23:03.814169 | 
2025-11-24 00:23:03.814300 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-24 00:23:04.190303 | controller | ok
2025-11-24 00:23:04.208461 | 
2025-11-24 00:23:04.208666 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-24 00:23:04.236815 | controller | skipping: Conditional result was False
2025-11-24 00:23:04.265480 | 
2025-11-24 00:23:04.265640 | TASK [include_role : remove-zuul-sshkey]
2025-11-24 00:23:04.292931 | controller | skipping: Conditional result was False
2025-11-24 00:23:04.302109 | 
2025-11-24 00:23:04.302213 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-24 00:23:04.531523 | controller | ok: "logs"
2025-11-24 00:23:04.532076 | controller | ok: All items complete
2025-11-24 00:23:04.532145 | 
2025-11-24 00:23:04.734983 | controller | ok: "artifacts"
2025-11-24 00:23:04.934501 | controller | ok: "docs"
2025-11-24 00:23:04.947412 | 
2025-11-24 00:23:04.947540 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-24 00:23:05.198471 | controller | changed: "logs"
2025-11-24 00:23:05.400050 | controller | changed: "artifacts"
2025-11-24 00:23:05.600926 | controller | changed: "docs"
2025-11-24 00:23:05.661853 | 
2025-11-24 00:23:05.661970 | PLAY RECAP
2025-11-24 00:23:05.662030 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-24 00:23:05.662066 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-24 00:23:05.662092 | 
2025-11-24 00:23:05.790035 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-24 00:23:05.791892 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-24 00:23:06.416813 | 
2025-11-24 00:23:06.416934 | PLAY [all]
2025-11-24 00:23:06.440667 | 
2025-11-24 00:23:06.440816 | TASK [Install binary dependencies]
2025-11-24 00:23:06.528774 | controller | ok
2025-11-24 00:23:06.561719 | 
2025-11-24 00:23:06.561877 | TASK [bindep : Include find tasks]
2025-11-24 00:23:06.595441 | controller | ok
2025-11-24 00:23:06.606808 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-24 00:23:06.616025 | 
2025-11-24 00:23:06.616115 | TASK [bindep : Look for bindep.txt]
2025-11-24 00:23:06.970945 | controller | ok
2025-11-24 00:23:06.985026 | 
2025-11-24 00:23:06.985234 | TASK [bindep : Define bindep_file fact]
2025-11-24 00:23:07.002160 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.010522 | 
2025-11-24 00:23:07.010654 | TASK [bindep : Look for other-requirements.txt]
2025-11-24 00:23:07.230034 | controller | ok
2025-11-24 00:23:07.242529 | 
2025-11-24 00:23:07.242723 | TASK [bindep : Define bindep_file fact]
2025-11-24 00:23:07.280052 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.295876 | 
2025-11-24 00:23:07.296097 | TASK [bindep : Look for bindep fallback file]
2025-11-24 00:23:07.333798 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.349161 | 
2025-11-24 00:23:07.349356 | TASK [bindep : Define bindep_file fact]
2025-11-24 00:23:07.386302 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.401304 | 
2025-11-24 00:23:07.401595 | TASK [bindep : Include bindep tasks]
2025-11-24 00:23:07.439154 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.453657 | 
2025-11-24 00:23:07.453875 | TASK [bindep : Include install tasks]
2025-11-24 00:23:07.491334 | controller | skipping: Conditional result was False
2025-11-24 00:23:07.505579 | 
2025-11-24 00:23:07.505808 | LOOP [bindep : Include package tasks]
2025-11-24 00:23:07.592511 | 
2025-11-24 00:23:07.592785 | TASK [Run test-setup role]
2025-11-24 00:23:07.621815 | controller | ok
2025-11-24 00:23:07.647174 | 
2025-11-24 00:23:07.647312 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-24 00:23:07.863187 | controller | ok
2025-11-24 00:23:07.871931 | 
2025-11-24 00:23:07.872032 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-24 00:23:08.421428 | controller | skipping: Conditional result was False
2025-11-24 00:23:08.476464 | 
2025-11-24 00:23:08.476603 | PLAY RECAP
2025-11-24 00:23:08.476670 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-24 00:23:08.476792 | 
2025-11-24 00:23:08.582982 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-24 00:23:08.583942 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-24 00:23:09.137909 | 
2025-11-24 00:23:09.138047 | PLAY [controller]
2025-11-24 00:23:09.158907 | 
2025-11-24 00:23:09.159055 | TASK [Create the /root directory]
2025-11-24 00:23:09.571439 | controller | ok
2025-11-24 00:23:09.584237 | 
2025-11-24 00:23:09.584412 | TASK [Install glibc-langpack-en]
2025-11-24 00:23:13.483382 | controller | ok: Nothing to do
2025-11-24 00:23:13.491641 | 
2025-11-24 00:23:13.491770 | TASK [Ensure controller directory exists]
2025-11-24 00:23:13.739557 | controller | changed
2025-11-24 00:23:13.748878 | 
2025-11-24 00:23:13.749035 | TASK [Install container runtime]
2025-11-24 00:23:13.816455 | controller | ok
2025-11-24 00:23:13.865353 | 
2025-11-24 00:23:13.865489 | LOOP [ensure-podman : Find distribution installation]
2025-11-24 00:23:13.907913 | controller | ok: "/var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-24 00:23:13.931727 | controller | included: /var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-24 00:23:13.941208 | 
2025-11-24 00:23:13.941308 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-24 00:24:32.251167 | controller | changed
2025-11-24 00:24:32.266015 | 
2025-11-24 00:24:32.266194 | TASK [ensure-podman : Fetch podman version]
2025-11-24 00:24:32.870887 | controller | Client:       Podman Engine
2025-11-24 00:24:32.903756 | controller | Version:      4.6.2
2025-11-24 00:24:32.903806 | controller | API Version:  4.6.2
2025-11-24 00:24:32.903819 | controller | Go Version:   go1.19.12
2025-11-24 00:24:32.903845 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-24 00:24:32.903857 | controller | OS/Arch:      linux/amd64
2025-11-24 00:24:33.317493 | controller | ok: Runtime: 0:00:00.221348
2025-11-24 00:24:33.332282 | 
2025-11-24 00:24:33.332493 | TASK [ensure-podman : Print podman version installed]
2025-11-24 00:24:33.364379 | Podman version: Client:       Podman Engine
2025-11-24 00:24:33.364662 | Version:      4.6.2
2025-11-24 00:24:33.364769 | API Version:  4.6.2
2025-11-24 00:24:33.364817 | Go Version:   go1.19.12
2025-11-24 00:24:33.364857 | Built:        Mon Aug 28 19:38:31 2023
2025-11-24 00:24:33.364899 | OS/Arch:      linux/amd64
2025-11-24 00:24:33.377996 | 
2025-11-24 00:24:33.378136 | TASK [ensure-podman : Validate podman engine]
2025-11-24 00:24:33.922939 | controller | skipping: Conditional result was False
2025-11-24 00:24:33.938564 | 
2025-11-24 00:24:33.938834 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-24 00:24:33.967032 | controller | skipping: Conditional result was False
2025-11-24 00:24:33.995303 | 
2025-11-24 00:24:33.995515 | TASK [Ensure python3.8 is present]
2025-11-24 00:24:34.023492 | controller | skipping: Conditional result was False
2025-11-24 00:24:34.036863 | 
2025-11-24 00:24:34.036997 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-24 00:24:34.067725 | controller | ok
2025-11-24 00:24:34.099635 | 
2025-11-24 00:24:34.099771 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-24 00:24:35.447167 | controller | ok: Nothing to do
2025-11-24 00:24:35.461140 | 
2025-11-24 00:24:35.461299 | TASK [our-ensure-python : Also install python3-devel]
2025-11-24 00:24:47.583737 | controller | changed
2025-11-24 00:24:47.614159 | 
2025-11-24 00:24:47.614418 | TASK [Run ensure-virtualenv role]
2025-11-24 00:24:47.646517 | controller | ok
2025-11-24 00:24:47.687117 | 
2025-11-24 00:24:47.687290 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-24 00:24:47.946694 | controller | /usr/bin/virtualenv
2025-11-24 00:24:48.256748 | controller | ok: Runtime: 0:00:00.004590
2025-11-24 00:24:48.270002 | 
2025-11-24 00:24:48.270151 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-24 00:24:48.305466 | controller | skipping: Conditional result was False
2025-11-24 00:24:48.305827 | controller | ok: All items complete
2025-11-24 00:24:48.305856 | 
2025-11-24 00:24:48.333510 | 
2025-11-24 00:24:48.333972 | TASK [Find the full path of the Python interpreter]
2025-11-24 00:24:48.594273 | controller | /usr/bin/python3
2025-11-24 00:24:48.891150 | controller | ok
2025-11-24 00:24:48.906726 | 
2025-11-24 00:24:48.906932 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-24 00:24:50.022007 | controller | created virtual environment CPython3.11.0.final.0-64 in 568ms
2025-11-24 00:24:50.045832 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-24 00:24:50.046287 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv)
2025-11-24 00:24:50.046360 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-24 00:24:50.046376 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-24 00:24:50.466244 | controller | changed
2025-11-24 00:24:50.475764 | 
2025-11-24 00:24:50.475862 | TASK [Set selinux package]
2025-11-24 00:24:50.511348 | controller | ok
2025-11-24 00:24:50.518878 | 
2025-11-24 00:24:50.518996 | TASK [Set selinux package (Fedora)]
2025-11-24 00:24:50.573512 | controller | ok
2025-11-24 00:24:50.580790 | 
2025-11-24 00:24:50.580879 | TASK [Install selinux into virtualenv]
2025-11-24 00:25:16.044644 | controller | Collecting selinux-please-lie-to-me
2025-11-24 00:25:28.329378 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-24 00:25:28.658980 | controller | Collecting setuptools<50.0.0
2025-11-24 00:25:28.666458 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-24 00:25:28.703721 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 24.6 MB/s eta 0:00:00
2025-11-24 00:25:28.784760 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-24 00:25:28.785003 | controller |   Attempting uninstall: setuptools
2025-11-24 00:25:28.787616 | controller |     Found existing installation: setuptools 62.6.0
2025-11-24 00:25:28.847689 | controller |     Uninstalling setuptools-62.6.0:
2025-11-24 00:25:28.855901 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-24 00:25:29.201973 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-24 00:25:40.671076 | controller |
2025-11-24 00:25:40.757073 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-24 00:25:40.757118 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-24 00:25:41.167884 | controller | ok: Runtime: 0:00:49.937002
2025-11-24 00:25:41.175955 | 
2025-11-24 00:25:41.176047 | TASK [Install pytest-forked into virtualenv]
2025-11-24 00:25:52.915195 | controller | Collecting pytest-forked
2025-11-24 00:26:03.116946 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-24 00:26:03.198077 | controller | Collecting py
2025-11-24 00:26:03.205163 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-24 00:26:03.224881 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.9 MB/s eta 0:00:00
2025-11-24 00:26:03.349254 | controller | Collecting pytest>=3.10
2025-11-24 00:26:03.354010 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-24 00:26:03.369953 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 30.9 MB/s eta 0:00:00
2025-11-24 00:26:03.418324 | controller | Collecting iniconfig>=1.0.1
2025-11-24 00:26:03.421639 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-24 00:26:03.467452 | controller | Collecting packaging>=22
2025-11-24 00:26:03.471301 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-24 00:26:03.477266 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 17.1 MB/s eta 0:00:00
2025-11-24 00:26:03.524450 | controller | Collecting pluggy<2,>=1.5
2025-11-24 00:26:03.528170 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-24 00:26:03.590719 | controller | Collecting pygments>=2.7.2
2025-11-24 00:26:03.594764 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-24 00:26:03.643658 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 27.0 MB/s eta 0:00:00
2025-11-24 00:26:03.712191 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-24 00:26:04.757644 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.1 pytest-forked-1.6.0
2025-11-24 00:26:04.766430 | controller |
2025-11-24 00:26:04.841976 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-24 00:26:04.842069 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-24 00:26:05.232214 | controller | ok: Runtime: 0:00:23.444285
2025-11-24 00:26:05.241605 | 
2025-11-24 00:26:05.241730 | TASK [Update pip]
2025-11-24 00:26:05.754678 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-24 00:26:18.192880 | controller | Collecting pip
2025-11-24 00:26:30.381043 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-24 00:26:30.457341 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 25.0 MB/s eta 0:00:00
2025-11-24 00:26:30.519745 | controller | Installing collected packages: pip
2025-11-24 00:26:30.519958 | controller |   Attempting uninstall: pip
2025-11-24 00:26:30.522116 | controller |     Found existing installation: pip 22.2.2
2025-11-24 00:26:30.656841 | controller |     Uninstalling pip-22.2.2:
2025-11-24 00:26:30.672757 | controller |       Successfully uninstalled pip-22.2.2
2025-11-24 00:26:31.452090 | controller | Successfully installed pip-25.3
2025-11-24 00:26:31.792289 | controller | ok: Runtime: 0:00:26.061522
2025-11-24 00:26:31.800717 | 
2025-11-24 00:26:31.800825 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-24 00:26:32.016909 | controller | changed
2025-11-24 00:26:32.024219 | 
2025-11-24 00:26:32.024303 | TASK [Install ansible into virtualenv]
2025-11-24 00:26:32.537655 | controller | Processing ./src/github.com/ansible/ansible
2025-11-24 00:26:32.540934 | controller |   Installing build dependencies: started
2025-11-24 00:26:57.851084 | controller |   Installing build dependencies: finished with status 'done'
2025-11-24 00:26:57.852157 | controller |   Getting requirements to build wheel: started
2025-11-24 00:26:58.590814 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-24 00:26:58.592106 | controller |   Preparing metadata (pyproject.toml): started
2025-11-24 00:26:59.050028 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-24 00:26:59.055509 | 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-11-24 00:26:59.059195 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-24 00:26:59.415826 | controller | ERROR
2025-11-24 00:26:59.416093 | controller | {
2025-11-24 00:26:59.416163 | controller |   "delta": "0:00:26.858354",
2025-11-24 00:26:59.416213 | controller |   "end": "2025-11-24 00:26:59.122931",
2025-11-24 00:26:59.416252 | controller |   "msg": "non-zero return code",
2025-11-24 00:26:59.416310 | controller |   "rc": 1,
2025-11-24 00:26:59.416350 | controller |   "start": "2025-11-24 00:26:32.264577"
2025-11-24 00:26:59.416385 | controller | }
failure
2025-11-24 00:26:59.419631 | 
2025-11-24 00:26:59.419811 | PLAY RECAP
2025-11-24 00:26:59.419909 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-24 00:26:59.419955 | 
2025-11-24 00:26:59.557257 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-24 00:26:59.560174 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-24 00:27:00.160495 | 
2025-11-24 00:27:00.160619 | PLAY [all]
2025-11-24 00:27:00.184298 | 
2025-11-24 00:27:00.184393 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-24 00:27:00.468611 | controller | changed: non-zero return code
2025-11-24 00:27:00.481921 | 
2025-11-24 00:27:00.482085 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-24 00:27:00.510601 | controller | skipping: Conditional result was False
2025-11-24 00:27:00.524075 | 
2025-11-24 00:27:00.524236 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-24 00:27:00.566185 | 
2025-11-24 00:27:00.566610 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-24 00:27:00.607874 | 
2025-11-24 00:27:00.608211 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-24 00:27:00.624911 | controller | skipping: Conditional result was False
2025-11-24 00:27:00.633455 | 
2025-11-24 00:27:00.633570 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-24 00:27:00.658750 | 
2025-11-24 00:27:00.658968 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-24 00:27:00.684834 | controller | skipping: Conditional result was False
2025-11-24 00:27:00.694966 | 
2025-11-24 00:27:00.695114 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-24 00:27:00.711183 | controller | skipping: Conditional result was False
2025-11-24 00:27:00.720780 | 
2025-11-24 00:27:00.720880 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-24 00:27:00.746352 | controller | skipping: Conditional result was False
2025-11-24 00:27:00.784222 | 
2025-11-24 00:27:00.784314 | PLAY RECAP
2025-11-24 00:27:00.784362 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-24 00:27:00.784383 | 
2025-11-24 00:27:00.978051 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-24 00:27:00.979870 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-24 00:27:01.603144 | 
2025-11-24 00:27:01.603267 | PLAY [all:!appliance*]
2025-11-24 00:27:01.625472 | 
2025-11-24 00:27:01.625575 | TASK [unregister the node]
2025-11-24 00:27:02.157779 | controller | skipping: Conditional result was False
2025-11-24 00:27:02.171754 | 
2025-11-24 00:27:02.171967 | TASK [include_role : fetch-output]
2025-11-24 00:27:02.223301 | controller | ok
2025-11-24 00:27:02.260346 | 
2025-11-24 00:27:02.260489 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-24 00:27:02.316744 | controller | skipping: Conditional result was False
2025-11-24 00:27:02.326277 | 
2025-11-24 00:27:02.326393 | TASK [fetch-output : Set log path for single node]
2025-11-24 00:27:02.379977 | controller | ok
2025-11-24 00:27:02.387438 | 
2025-11-24 00:27:02.387527 | LOOP [fetch-output : Ensure local output dirs]
2025-11-24 00:27:02.839406 | controller -> localhost | ok: "/var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/logs"
2025-11-24 00:27:03.076064 | controller -> localhost | changed: "/var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/artifacts"
2025-11-24 00:27:03.296580 | controller -> localhost | changed: "/var/lib/zuul/builds/76a7a07671de46e19dbe219872fa0e9c/work/docs"
2025-11-24 00:27:03.325362 | 
2025-11-24 00:27:03.325569 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-24 00:27:04.038101 | controller | changed:
2025-11-24 00:27:04.038325 | controller | .d..t...... ./
2025-11-24 00:27:04.038369 | controller | cd+++++++++ controller/
2025-11-24 00:27:04.038411 | controller | changed: All items complete
2025-11-24 00:27:04.038433 | 
2025-11-24 00:27:04.542853 | controller | changed: .d..t...... ./
2025-11-24 00:27:05.090830 | controller | changed: .d..t...... ./
2025-11-24 00:27:05.124055 | 
2025-11-24 00:27:05.124237 | TASK [include_role : fetch-output-openshift]
2025-11-24 00:27:05.149488 | controller | skipping: Conditional result was False
2025-11-24 00:27:05.158850 | 
2025-11-24 00:27:05.158952 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-24 00:27:05.202119 | controller | skipping: Conditional result was False
2025-11-24 00:27:05.216618 | controller | skipping: Conditional result was False
2025-11-24 00:27:05.252644 | 
2025-11-24 00:27:05.252967 | PLAY [localhost]
2025-11-24 00:27:05.265142 | 
2025-11-24 00:27:05.265212 | TASK [Run Zuul manifest role]
2025-11-24 00:27:05.282820 | localhost | ok
2025-11-24 00:27:05.296551 | 
2025-11-24 00:27:05.296626 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-24 00:27:05.737277 | localhost | changed
2025-11-24 00:27:05.747637 | 
2025-11-24 00:27:05.747823 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-24 00:27:05.793859 | localhost | ok
2025-11-24 00:27:05.811926 | 
2025-11-24 00:27:05.812060 | TASK [Set zuul-log-path fact]
2025-11-24 00:27:05.833474 | localhost | ok
2025-11-24 00:27:05.852746 | 
2025-11-24 00:27:05.852920 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-24 00:27:05.892615 | localhost | ok
2025-11-24 00:27:05.903905 | 
2025-11-24 00:27:05.903987 | LOOP [Run upload-logs-swift role]
2025-11-24 00:27:05.949624 | localhost | Output suppressed because no_log was given
2025-11-24 00:27:05.982990 | 
2025-11-24 00:27:05.983146 | TASK [Set zuul-log-path fact]
2025-11-24 00:27:06.018916 | localhost | skipping: Conditional result was False
2025-11-24 00:27:06.026510 | 
2025-11-24 00:27:06.026645 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-24 00:27:06.543341 | localhost -> localhost | ok: Runtime: 0:00:00.009619
2025-11-24 00:27:06.577447 | 
2025-11-24 00:27:06.577547 | TASK [upload-logs-swift : Upload logs to swift]