2026-01-13 00:21:24.216506 | Job console starting...
2026-01-13 00:21:24.228587 | Updating repositories
2026-01-13 00:21:24.403767 | Preparing job workspace
2026-01-13 00:21:28.250442 | Running Ansible setup...
2026-01-13 00:21:36.236118 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-13 00:21:36.951008 | 
2026-01-13 00:21:36.951158 | PLAY [localhost]
2026-01-13 00:21:36.959809 | 
2026-01-13 00:21:36.959883 | TASK [Gathering Facts]
2026-01-13 00:21:38.007224 | localhost | ok
2026-01-13 00:21:38.025433 | 
2026-01-13 00:21:38.025543 | TASK [Setup log path fact]
2026-01-13 00:21:38.047154 | localhost | ok
2026-01-13 00:21:38.063905 | 
2026-01-13 00:21:38.063996 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-13 00:21:38.103978 | localhost | ok
2026-01-13 00:21:38.114626 | 
2026-01-13 00:21:38.114753 | TASK [emit-job-header : Print job information]
2026-01-13 00:21:38.145299 | # Job Information
2026-01-13 00:21:38.145512 | Ansible Version: 2.15.12
2026-01-13 00:21:38.145556 | Job: ansible-test-sanity-docker-milestone
2026-01-13 00:21:38.145589 | Pipeline: periodic
2026-01-13 00:21:38.145616 | Executor: ze02.softwarefactory-project.io
2026-01-13 00:21:38.145641 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-13 00:21:38.145699 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/5f0/ansible/5f070522cdd24654846904438c410022/
2026-01-13 00:21:38.145730 | Event ID: c4f09769d5af45b29afe2e93570d6015
2026-01-13 00:21:38.150889 | 
2026-01-13 00:21:38.150975 | LOOP [emit-job-header : Print node information]
2026-01-13 00:21:38.257224 | localhost | ok:
2026-01-13 00:21:38.257484 | localhost | # Node Information
2026-01-13 00:21:38.257552 | localhost | Inventory Hostname: controller
2026-01-13 00:21:38.257602 | localhost | Hostname: np0005582388
2026-01-13 00:21:38.257651 | localhost | Username: zuul
2026-01-13 00:21:38.257747 | localhost | Distro: Fedora 37
2026-01-13 00:21:38.257796 | localhost | Provider: ansible-vexxhost-ams1
2026-01-13 00:21:38.257841 | localhost | Region: ams1
2026-01-13 00:21:38.257885 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-13 00:21:38.257928 | localhost | Product Name: OpenStack Nova
2026-01-13 00:21:38.257971 | localhost | Interface IP: 38.129.16.183
2026-01-13 00:21:38.275467 | 
2026-01-13 00:21:38.275606 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-13 00:21:38.740655 | localhost -> localhost | changed
2026-01-13 00:21:38.746854 | 
2026-01-13 00:21:38.746924 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-13 00:21:39.708469 | localhost -> localhost | changed
2026-01-13 00:21:39.770808 | 
2026-01-13 00:21:39.770934 | PLAY [all:!appliance*]
2026-01-13 00:21:39.794728 | 
2026-01-13 00:21:39.794820 | TASK [include_role : start-zuul-console]
2026-01-13 00:21:39.819565 | controller | ok
2026-01-13 00:21:39.838997 | 
2026-01-13 00:21:39.839085 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-13 00:21:40.904455 | controller | ok
2026-01-13 00:21:40.932658 | 
2026-01-13 00:21:40.932867 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-13 00:21:44.040801 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-13 00:21:44.056940 | 
2026-01-13 00:21:44.057095 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-13 00:21:44.428042 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.444917 | 
2026-01-13 00:21:44.445094 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-13 00:21:44.475227 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.500640 | 
2026-01-13 00:21:44.500931 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-13 00:21:44.527700 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.541525 | 
2026-01-13 00:21:44.541720 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-13 00:21:44.568940 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.583081 | 
2026-01-13 00:21:44.583226 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-13 00:21:44.610731 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.624450 | 
2026-01-13 00:21:44.624597 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-13 00:21:44.652932 | controller | skipping: Conditional result was False
2026-01-13 00:21:44.682778 | 
2026-01-13 00:21:44.682992 | TASK [Disable Fedora Modular]
2026-01-13 00:21:45.761550 | controller | changed
2026-01-13 00:21:45.775353 | 
2026-01-13 00:21:45.775486 | TASK [Enable EPEL]
2026-01-13 00:21:45.804551 | controller | skipping: Conditional result was False
2026-01-13 00:21:45.814976 | 
2026-01-13 00:21:45.815070 | TASK [Register the RHEL node]
2026-01-13 00:21:46.237910 | 
2026-01-13 00:21:46.238240 | TASK [Show the subscription-manager status]
2026-01-13 00:21:46.615287 | controller | skipping: Conditional result was False
2026-01-13 00:21:46.630046 | 
2026-01-13 00:21:46.630212 | TASK [Enable EPEL on RHEL]
2026-01-13 00:21:47.051565 | controller | skipping: Conditional result was False
2026-01-13 00:21:47.067641 | 
2026-01-13 00:21:47.067859 | TASK [Install git and tox]
2026-01-13 00:23:57.350894 | controller | changed
2026-01-13 00:23:57.368212 | 
2026-01-13 00:23:57.368429 | TASK [include_role : prepare-workspace]
2026-01-13 00:23:57.403018 | controller | ok
2026-01-13 00:23:57.442576 | 
2026-01-13 00:23:57.442753 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-13 00:23:58.300471 | controller | ok
2026-01-13 00:23:58.307503 | 
2026-01-13 00:23:58.307565 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-13 00:24:13.952735 | controller | Output suppressed because no_log was given
2026-01-13 00:24:13.965113 | 
2026-01-13 00:24:13.965189 | TASK [include_role : prepare-workspace-openshift]
2026-01-13 00:24:13.994346 | controller | skipping: Conditional result was False
2026-01-13 00:24:14.019527 | 
2026-01-13 00:24:14.019634 | PLAY [all:!appliance]
2026-01-13 00:24:14.037231 | 
2026-01-13 00:24:14.037356 | TASK [Run add-build-sshkey role (RSA)]
2026-01-13 00:24:14.069153 | controller | ok
2026-01-13 00:24:14.086357 | 
2026-01-13 00:24:14.086483 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-13 00:24:14.346357 | controller -> localhost | ok
2026-01-13 00:24:14.353108 | 
2026-01-13 00:24:14.353171 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-13 00:24:14.383486 | controller | ok
2026-01-13 00:24:14.397857 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-13 00:24:14.404417 | 
2026-01-13 00:24:14.404477 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-13 00:24:14.888988 | controller -> localhost | Generating public/private rsa key pair.
2026-01-13 00:24:14.889455 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_rsa.
2026-01-13 00:24:14.889526 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_rsa.pub.
2026-01-13 00:24:14.889575 | controller -> localhost | The key fingerprint is:
2026-01-13 00:24:14.889620 | controller -> localhost | SHA256:0YkbO8aA7ZZK9foKxdB0jW40RqpJMNzku8dU+94UCdo zuul-build-sshkey
2026-01-13 00:24:14.889695 | controller -> localhost | The key's randomart image is:
2026-01-13 00:24:14.889750 | controller -> localhost | +---[RSA 2048]----+
2026-01-13 00:24:14.889792 | controller -> localhost | | .oo. ..oo       |
2026-01-13 00:24:14.889836 | controller -> localhost | |  .+.= o=o..     |
2026-01-13 00:24:14.889877 | controller -> localhost | |    = *+=.+      |
2026-01-13 00:24:14.889919 | controller -> localhost | |   . O *oO . .   |
2026-01-13 00:24:14.889959 | controller -> localhost | |    = B.S E o    |
2026-01-13 00:24:14.890018 | controller -> localhost | |   . B o o   .   |
2026-01-13 00:24:14.890067 | controller -> localhost | |    + +   . .    |
2026-01-13 00:24:14.890111 | controller -> localhost | |     o . . o     |
2026-01-13 00:24:14.890153 | controller -> localhost | |      ... . .    |
2026-01-13 00:24:14.890202 | controller -> localhost | +----[SHA256]-----+
2026-01-13 00:24:14.890309 | controller -> localhost | ok: Runtime: 0:00:00.085677
2026-01-13 00:24:14.906515 | 
2026-01-13 00:24:14.906655 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-13 00:24:14.951308 | controller | ok
2026-01-13 00:24:14.973834 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-13 00:24:14.987987 | 
2026-01-13 00:24:14.988089 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-13 00:24:15.014699 | controller | skipping: Conditional result was False
2026-01-13 00:24:15.025328 | 
2026-01-13 00:24:15.025434 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-13 00:24:16.117205 | controller | changed
2026-01-13 00:24:16.131721 | 
2026-01-13 00:24:16.131867 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-13 00:24:16.807849 | controller | ok
2026-01-13 00:24:16.823134 | 
2026-01-13 00:24:16.823287 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-13 00:24:19.952065 | controller | changed
2026-01-13 00:24:19.965394 | 
2026-01-13 00:24:19.965539 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-13 00:24:23.015269 | controller | changed
2026-01-13 00:24:23.021060 | 
2026-01-13 00:24:23.021128 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-13 00:24:23.037586 | controller | skipping: Conditional result was False
2026-01-13 00:24:23.051987 | 
2026-01-13 00:24:23.052136 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-13 00:24:23.424485 | controller -> localhost | changed
2026-01-13 00:24:23.450484 | 
2026-01-13 00:24:23.450653 | TASK [add-build-sshkey : Add back temp key]
2026-01-13 00:24:23.845417 | controller -> localhost | Identity added: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_rsa (zuul-build-sshkey)
2026-01-13 00:24:23.845644 | controller -> localhost | ok: Runtime: 0:00:00.008763
2026-01-13 00:24:23.853730 | 
2026-01-13 00:24:23.853797 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-13 00:24:24.800655 | controller | ok
2026-01-13 00:24:24.814080 | 
2026-01-13 00:24:24.814253 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-13 00:24:24.842825 | controller | skipping: Conditional result was False
2026-01-13 00:24:24.870750 | 
2026-01-13 00:24:24.870943 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-13 00:24:24.914067 | controller | ok
2026-01-13 00:24:24.939591 | 
2026-01-13 00:24:24.939731 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-13 00:24:25.201014 | controller -> localhost | ok
2026-01-13 00:24:25.215732 | 
2026-01-13 00:24:25.215908 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-13 00:24:25.254360 | controller | ok
2026-01-13 00:24:25.280839 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-13 00:24:25.290636 | 
2026-01-13 00:24:25.290777 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-13 00:24:25.612040 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-13 00:24:25.612370 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_ecdsa.
2026-01-13 00:24:25.612408 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_ecdsa.pub.
2026-01-13 00:24:25.612449 | controller -> localhost | The key fingerprint is:
2026-01-13 00:24:25.612480 | controller -> localhost | SHA256:bMMEKgDo6RcCemIocwimnT4Dh5k7zZMt/Ee7PbiM8CM zuul-build-sshkey
2026-01-13 00:24:25.612510 | controller -> localhost | The key's randomart image is:
2026-01-13 00:24:25.612539 | controller -> localhost | +---[ECDSA 521]---+
2026-01-13 00:24:25.612563 | controller -> localhost | |=     .          |
2026-01-13 00:24:25.612588 | controller -> localhost | |+o   . .         |
2026-01-13 00:24:25.612614 | controller -> localhost | |O*o..   .        |
2026-01-13 00:24:25.612643 | controller -> localhost | |&=*o   +         |
2026-01-13 00:24:25.612699 | controller -> localhost | |+&.o.   S        |
2026-01-13 00:24:25.612731 | controller -> localhost | |o.@.. .. .       |
2026-01-13 00:24:25.612758 | controller -> localhost | | .o* . o         |
2026-01-13 00:24:25.612782 | controller -> localhost | |  Eooo+..        |
2026-01-13 00:24:25.612805 | controller -> localhost | |   .oo+o..       |
2026-01-13 00:24:25.612828 | controller -> localhost | +----[SHA256]-----+
2026-01-13 00:24:25.612893 | controller -> localhost | ok: Runtime: 0:00:00.015000
2026-01-13 00:24:25.623507 | 
2026-01-13 00:24:25.623728 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-13 00:24:25.660414 | controller | ok
2026-01-13 00:24:25.673030 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-13 00:24:25.690274 | 
2026-01-13 00:24:25.690521 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-13 00:24:25.716487 | controller | skipping: Conditional result was False
2026-01-13 00:24:25.769167 | 
2026-01-13 00:24:25.769313 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-13 00:24:26.734408 | controller | changed
2026-01-13 00:24:26.747727 | 
2026-01-13 00:24:26.747870 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-13 00:24:27.452881 | controller | ok
2026-01-13 00:24:27.469193 | 
2026-01-13 00:24:27.469338 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-13 00:24:30.608169 | controller | changed
2026-01-13 00:24:30.614325 | 
2026-01-13 00:24:30.614394 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-13 00:24:33.721328 | controller | changed
2026-01-13 00:24:33.731287 | 
2026-01-13 00:24:33.731431 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-13 00:24:33.758234 | controller | skipping: Conditional result was False
2026-01-13 00:24:33.767697 | 
2026-01-13 00:24:33.767798 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-13 00:24:34.047795 | controller -> localhost | changed
2026-01-13 00:24:34.078602 | 
2026-01-13 00:24:34.078931 | TASK [add-build-sshkey : Add back temp key]
2026-01-13 00:24:34.424325 | controller -> localhost | Identity added: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/5f070522cdd24654846904438c410022_id_ecdsa (zuul-build-sshkey)
2026-01-13 00:24:34.424616 | controller -> localhost | ok: Runtime: 0:00:00.014214
2026-01-13 00:24:34.431440 | 
2026-01-13 00:24:34.431559 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-13 00:24:35.161890 | controller | ok
2026-01-13 00:24:35.173979 | 
2026-01-13 00:24:35.174112 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-13 00:24:35.211942 | controller | skipping: Conditional result was False
2026-01-13 00:24:35.237067 | 
2026-01-13 00:24:35.237242 | TASK [include_role : remove-zuul-sshkey]
2026-01-13 00:24:35.263741 | controller | skipping: Conditional result was False
2026-01-13 00:24:35.280399 | 
2026-01-13 00:24:35.280581 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-13 00:24:35.933132 | controller | ok: "logs"
2026-01-13 00:24:35.933449 | controller | ok: All items complete
2026-01-13 00:24:35.933490 | 
2026-01-13 00:24:36.557926 | controller | ok: "artifacts"
2026-01-13 00:24:37.180349 | controller | ok: "docs"
2026-01-13 00:24:37.202797 | 
2026-01-13 00:24:37.203074 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-13 00:24:37.884862 | controller | changed: "logs"
2026-01-13 00:24:38.525880 | controller | changed: "artifacts"
2026-01-13 00:24:39.185815 | controller | changed: "docs"
2026-01-13 00:24:39.251054 | 
2026-01-13 00:24:39.251201 | PLAY RECAP
2026-01-13 00:24:39.251275 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-13 00:24:39.251312 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-13 00:24:39.251338 | 
2026-01-13 00:24:39.413315 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-13 00:24:39.414222 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-13 00:24:40.003558 | 
2026-01-13 00:24:40.003780 | PLAY [all]
2026-01-13 00:24:40.027781 | 
2026-01-13 00:24:40.027916 | TASK [Install binary dependencies]
2026-01-13 00:24:40.100257 | controller | ok
2026-01-13 00:24:40.121642 | 
2026-01-13 00:24:40.121809 | TASK [bindep : Include find tasks]
2026-01-13 00:24:40.154975 | controller | ok
2026-01-13 00:24:40.165700 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-13 00:24:40.174306 | 
2026-01-13 00:24:40.174383 | TASK [bindep : Look for bindep.txt]
2026-01-13 00:24:41.161736 | controller | ok
2026-01-13 00:24:41.175613 | 
2026-01-13 00:24:41.175828 | TASK [bindep : Define bindep_file fact]
2026-01-13 00:24:41.194650 | controller | skipping: Conditional result was False
2026-01-13 00:24:41.213025 | 
2026-01-13 00:24:41.213257 | TASK [bindep : Look for other-requirements.txt]
2026-01-13 00:24:41.859239 | controller | ok
2026-01-13 00:24:41.868187 | 
2026-01-13 00:24:41.868379 | TASK [bindep : Define bindep_file fact]
2026-01-13 00:24:41.893370 | controller | skipping: Conditional result was False
2026-01-13 00:24:41.905020 | 
2026-01-13 00:24:41.905111 | TASK [bindep : Look for bindep fallback file]
2026-01-13 00:24:41.930922 | controller | skipping: Conditional result was False
2026-01-13 00:24:41.940040 | 
2026-01-13 00:24:41.940155 | TASK [bindep : Define bindep_file fact]
2026-01-13 00:24:41.965028 | controller | skipping: Conditional result was False
2026-01-13 00:24:41.974599 | 
2026-01-13 00:24:41.974740 | TASK [bindep : Include bindep tasks]
2026-01-13 00:24:41.999815 | controller | skipping: Conditional result was False
2026-01-13 00:24:42.008469 | 
2026-01-13 00:24:42.008575 | TASK [bindep : Include install tasks]
2026-01-13 00:24:42.033759 | controller | skipping: Conditional result was False
2026-01-13 00:24:42.043333 | 
2026-01-13 00:24:42.043581 | LOOP [bindep : Include package tasks]
2026-01-13 00:24:42.111382 | 
2026-01-13 00:24:42.111555 | TASK [Run test-setup role]
2026-01-13 00:24:42.131294 | controller | ok
2026-01-13 00:24:42.151009 | 
2026-01-13 00:24:42.151168 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-13 00:24:42.813913 | controller | ok
2026-01-13 00:24:42.828353 | 
2026-01-13 00:24:42.828490 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-13 00:24:43.197850 | controller | skipping: Conditional result was False
2026-01-13 00:24:43.263609 | 
2026-01-13 00:24:43.263774 | PLAY RECAP
2026-01-13 00:24:43.263839 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-13 00:24:43.263868 | 
2026-01-13 00:24:43.390698 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-13 00:24:43.391595 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-13 00:24:44.056124 | 
2026-01-13 00:24:44.056278 | PLAY [controller]
2026-01-13 00:24:44.076604 | 
2026-01-13 00:24:44.076754 | TASK [Create the /root directory]
2026-01-13 00:24:45.137139 | controller | ok
2026-01-13 00:24:45.153233 | 
2026-01-13 00:24:45.153426 | TASK [Install glibc-langpack-en]
2026-01-13 00:24:53.848249 | controller | ok: Nothing to do
2026-01-13 00:24:53.866388 | 
2026-01-13 00:24:53.866567 | TASK [Ensure controller directory exists]
2026-01-13 00:24:54.743543 | controller | changed
2026-01-13 00:24:54.756754 | 
2026-01-13 00:24:54.756915 | TASK [Install container runtime]
2026-01-13 00:24:54.815112 | controller | ok
2026-01-13 00:24:54.858202 | 
2026-01-13 00:24:54.858332 | LOOP [ensure-podman : Find distribution installation]
2026-01-13 00:24:54.902643 | controller | ok: "/var/lib/zuul/builds/5f070522cdd24654846904438c410022/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-13 00:24:54.910778 | controller | included: /var/lib/zuul/builds/5f070522cdd24654846904438c410022/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-13 00:24:54.918727 | 
2026-01-13 00:24:54.918806 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-13 00:26:58.497163 | controller | changed
2026-01-13 00:26:58.510733 | 
2026-01-13 00:26:58.510895 | TASK [ensure-podman : Fetch podman version]
2026-01-13 00:26:59.761722 | controller | Client:       Podman Engine
2026-01-13 00:26:59.807542 | controller | Version:      4.6.2
2026-01-13 00:26:59.807626 | controller | API Version:  4.6.2
2026-01-13 00:26:59.807638 | controller | Go Version:   go1.19.12
2026-01-13 00:26:59.807663 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-13 00:26:59.807672 | controller | OS/Arch:      linux/amd64
2026-01-13 00:27:00.398406 | controller | ok: Runtime: 0:00:00.323736
2026-01-13 00:27:00.412532 | 
2026-01-13 00:27:00.412710 | TASK [ensure-podman : Print podman version installed]
2026-01-13 00:27:00.452238 | Podman version: Client:       Podman Engine
2026-01-13 00:27:00.452553 | Version:      4.6.2
2026-01-13 00:27:00.452617 | API Version:  4.6.2
2026-01-13 00:27:00.452712 | Go Version:   go1.19.12
2026-01-13 00:27:00.452768 | Built:        Mon Aug 28 19:38:31 2023
2026-01-13 00:27:00.452814 | OS/Arch:      linux/amd64
2026-01-13 00:27:00.465336 | 
2026-01-13 00:27:00.465467 | TASK [ensure-podman : Validate podman engine]
2026-01-13 00:27:00.838158 | controller | skipping: Conditional result was False
2026-01-13 00:27:00.852818 | 
2026-01-13 00:27:00.853009 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-13 00:27:00.871723 | controller | skipping: Conditional result was False
2026-01-13 00:27:00.904536 | 
2026-01-13 00:27:00.904868 | TASK [Ensure python3.8 is present]
2026-01-13 00:27:00.931920 | controller | skipping: Conditional result was False
2026-01-13 00:27:00.940569 | 
2026-01-13 00:27:00.940705 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-13 00:27:00.969660 | controller | ok
2026-01-13 00:27:01.004692 | 
2026-01-13 00:27:01.004892 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-13 00:27:04.818335 | controller | ok: Nothing to do
2026-01-13 00:27:04.826480 | 
2026-01-13 00:27:04.826568 | TASK [our-ensure-python : Also install python3-devel]
2026-01-13 00:27:22.310419 | controller | changed
2026-01-13 00:27:22.338206 | 
2026-01-13 00:27:22.338416 | TASK [Run ensure-virtualenv role]
2026-01-13 00:27:22.365232 | controller | ok
2026-01-13 00:27:22.397021 | 
2026-01-13 00:27:22.397217 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-13 00:27:23.205033 | controller | /usr/bin/virtualenv
2026-01-13 00:27:23.803221 | controller | ok: Runtime: 0:00:00.007498
2026-01-13 00:27:23.816153 | 
2026-01-13 00:27:23.816297 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-13 00:27:23.845545 | controller | skipping: Conditional result was False
2026-01-13 00:27:23.846071 | controller | ok: All items complete
2026-01-13 00:27:23.846132 | 
2026-01-13 00:27:23.869333 | 
2026-01-13 00:27:23.869610 | TASK [Find the full path of the Python interpreter]
2026-01-13 00:27:24.662824 | controller | /usr/bin/python3
2026-01-13 00:27:25.231680 | controller | ok
2026-01-13 00:27:25.238871 | 
2026-01-13 00:27:25.239039 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-13 00:27:27.493838 | controller | created virtual environment CPython3.11.0.final.0-64 in 1050ms
2026-01-13 00:27:27.553084 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-13 00:27:27.553189 | 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)
2026-01-13 00:27:27.553212 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-13 00:27:27.553236 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-13 00:27:28.118054 | controller | changed
2026-01-13 00:27:28.124606 | 
2026-01-13 00:27:28.124749 | TASK [Set selinux package]
2026-01-13 00:27:28.155147 | controller | ok
2026-01-13 00:27:28.161252 | 
2026-01-13 00:27:28.161338 | TASK [Set selinux package (Fedora)]
2026-01-13 00:27:28.201658 | controller | ok
2026-01-13 00:27:28.206864 | 
2026-01-13 00:27:28.206927 | TASK [Install selinux into virtualenv]
2026-01-13 00:27:31.690350 | controller | Collecting selinux-please-lie-to-me
2026-01-13 00:27:31.771036 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-13 00:27:32.313526 | controller | Collecting setuptools<50.0.0
2026-01-13 00:27:32.320041 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-13 00:27:32.391054 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 12.3 MB/s eta 0:00:00
2026-01-13 00:27:32.531944 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-13 00:27:32.532300 | controller |   Attempting uninstall: setuptools
2026-01-13 00:27:32.536833 | controller |     Found existing installation: setuptools 62.6.0
2026-01-13 00:27:32.650623 | controller |     Uninstalling setuptools-62.6.0:
2026-01-13 00:27:32.664312 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-13 00:27:33.573089 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-13 00:27:33.808275 | controller |
2026-01-13 00:27:34.285691 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-13 00:27:34.285755 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-13 00:27:34.593062 | controller | ok: Runtime: 0:00:05.266844
2026-01-13 00:27:34.601462 | 
2026-01-13 00:27:34.601557 | TASK [Install pytest-forked into virtualenv]
2026-01-13 00:27:36.196757 | controller | Collecting pytest-forked
2026-01-13 00:27:36.270208 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-13 00:27:36.349230 | controller | Collecting py
2026-01-13 00:27:36.357690 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-13 00:27:36.397805 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.7 MB/s eta 0:00:00
2026-01-13 00:27:36.586498 | controller | Collecting pytest>=3.10
2026-01-13 00:27:36.595019 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-13 00:27:36.616987 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 23.1 MB/s eta 0:00:00
2026-01-13 00:27:36.694982 | controller | Collecting iniconfig>=1.0.1
2026-01-13 00:27:36.702912 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-13 00:27:36.798434 | controller | Collecting packaging>=22
2026-01-13 00:27:36.803268 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2026-01-13 00:27:36.812318 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.3 MB/s eta 0:00:00
2026-01-13 00:27:36.862685 | controller | Collecting pluggy<2,>=1.5
2026-01-13 00:27:36.871926 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-13 00:27:36.953635 | controller | Collecting pygments>=2.7.2
2026-01-13 00:27:36.959280 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-13 00:27:36.985764 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 54.4 MB/s eta 0:00:00
2026-01-13 00:27:37.115467 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-13 00:27:39.694956 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2026-01-13 00:27:39.717838 | controller |
2026-01-13 00:27:40.102818 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-13 00:27:40.102888 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-13 00:27:40.462490 | controller | ok: Runtime: 0:00:04.695613
2026-01-13 00:27:40.475555 | 
2026-01-13 00:27:40.475736 | TASK [Update pip]
2026-01-13 00:27:41.911333 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-13 00:27:42.273587 | controller | Collecting pip
2026-01-13 00:27:42.335417 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-13 00:27:42.415505 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 23.6 MB/s eta 0:00:00
2026-01-13 00:27:42.536681 | controller | Installing collected packages: pip
2026-01-13 00:27:42.541736 | controller |   Attempting uninstall: pip
2026-01-13 00:27:42.541760 | controller |     Found existing installation: pip 22.2.2
2026-01-13 00:27:42.777294 | controller |     Uninstalling pip-22.2.2:
2026-01-13 00:27:42.804852 | controller |       Successfully uninstalled pip-22.2.2
2026-01-13 00:27:44.719266 | controller | Successfully installed pip-25.3
2026-01-13 00:27:45.364528 | controller | ok: Runtime: 0:00:03.722514
2026-01-13 00:27:45.372774 | 
2026-01-13 00:27:45.372872 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-13 00:27:46.363046 | controller | changed
2026-01-13 00:27:46.376483 | 
2026-01-13 00:27:46.376623 | TASK [Install ansible into virtualenv]
2026-01-13 00:27:47.574294 | controller | Processing ./src/github.com/ansible/ansible
2026-01-13 00:27:47.583525 | controller |   Installing build dependencies: started
2026-01-13 00:27:49.776894 | controller |   Installing build dependencies: finished with status 'done'
2026-01-13 00:27:49.786227 | controller |   Getting requirements to build wheel: started
2026-01-13 00:27:51.420733 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-13 00:27:51.422809 | controller |   Preparing metadata (pyproject.toml): started
2026-01-13 00:27:52.411584 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-13 00:27:52.416556 | 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.
2026-01-13 00:27:52.420799 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-13 00:27:53.276028 | controller | ERROR
2026-01-13 00:27:53.276453 | controller | {
2026-01-13 00:27:53.276519 | controller |   "delta": "0:00:05.677466",
2026-01-13 00:27:53.276561 | controller |   "end": "2026-01-13 00:27:52.702433",
2026-01-13 00:27:53.276600 | controller |   "msg": "non-zero return code",
2026-01-13 00:27:53.276766 | controller |   "rc": 1,
2026-01-13 00:27:53.276830 | controller |   "start": "2026-01-13 00:27:47.024967"
2026-01-13 00:27:53.276868 | controller | }
failure
2026-01-13 00:27:53.280445 | 
2026-01-13 00:27:53.280547 | PLAY RECAP
2026-01-13 00:27:53.280703 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-13 00:27:53.280763 | 
2026-01-13 00:27:53.472250 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-13 00:27:53.474624 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-13 00:27:54.155076 | 
2026-01-13 00:27:54.155260 | PLAY [all]
2026-01-13 00:27:54.180865 | 
2026-01-13 00:27:54.181055 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-13 00:27:56.070886 | controller | changed: non-zero return code
2026-01-13 00:27:56.084128 | 
2026-01-13 00:27:56.084313 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-13 00:27:56.102936 | controller | skipping: Conditional result was False
2026-01-13 00:27:56.117486 | 
2026-01-13 00:27:56.117742 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-13 00:27:56.160775 | 
2026-01-13 00:27:56.161981 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-13 00:27:56.202368 | 
2026-01-13 00:27:56.202955 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-13 00:27:56.230209 | controller | skipping: Conditional result was False
2026-01-13 00:27:56.237160 | 
2026-01-13 00:27:56.237236 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-13 00:27:56.269847 | 
2026-01-13 00:27:56.270092 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-13 00:27:56.295349 | controller | skipping: Conditional result was False
2026-01-13 00:27:56.305307 | 
2026-01-13 00:27:56.305420 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-13 00:27:56.330654 | controller | skipping: Conditional result was False
2026-01-13 00:27:56.342634 | 
2026-01-13 00:27:56.342793 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-13 00:27:56.371890 | controller | skipping: Conditional result was False
2026-01-13 00:27:56.416200 | 
2026-01-13 00:27:56.416468 | PLAY RECAP
2026-01-13 00:27:56.416517 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-13 00:27:56.416538 | 
2026-01-13 00:27:56.573219 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-13 00:27:56.574245 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-13 00:27:57.236305 | 
2026-01-13 00:27:57.236481 | PLAY [all:!appliance*]
2026-01-13 00:27:57.258586 | 
2026-01-13 00:27:57.258690 | TASK [unregister the node]
2026-01-13 00:27:57.617970 | controller | skipping: Conditional result was False
2026-01-13 00:27:57.630856 | 
2026-01-13 00:27:57.631034 | TASK [include_role : fetch-output]
2026-01-13 00:27:57.690723 | controller | ok
2026-01-13 00:27:57.727816 | 
2026-01-13 00:27:57.727915 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-13 00:27:57.793889 | controller | skipping: Conditional result was False
2026-01-13 00:27:57.808696 | 
2026-01-13 00:27:57.808862 | TASK [fetch-output : Set log path for single node]
2026-01-13 00:27:57.869424 | controller | ok
2026-01-13 00:27:57.881945 | 
2026-01-13 00:27:57.882094 | LOOP [fetch-output : Ensure local output dirs]
2026-01-13 00:27:58.357859 | controller -> localhost | ok: "/var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/logs"
2026-01-13 00:27:58.679534 | controller -> localhost | changed: "/var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/artifacts"
2026-01-13 00:27:58.963383 | controller -> localhost | changed: "/var/lib/zuul/builds/5f070522cdd24654846904438c410022/work/docs"
2026-01-13 00:27:58.975639 | 
2026-01-13 00:27:58.975818 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-13 00:28:01.294560 | controller | changed:
2026-01-13 00:28:01.295149 | controller | .d..t...... ./
2026-01-13 00:28:01.295227 | controller | cd+++++++++ controller/
2026-01-13 00:28:01.295309 | controller | changed: All items complete
2026-01-13 00:28:01.295359 | 
2026-01-13 00:28:03.448324 | controller | changed: .d..t...... ./
2026-01-13 00:28:05.547299 | controller | changed: .d..t...... ./
2026-01-13 00:28:05.582040 | 
2026-01-13 00:28:05.582268 | TASK [include_role : fetch-output-openshift]
2026-01-13 00:28:05.611907 | controller | skipping: Conditional result was False
2026-01-13 00:28:05.623280 | 
2026-01-13 00:28:05.623378 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-13 00:28:05.668132 | controller | skipping: Conditional result was False
2026-01-13 00:28:05.677549 | controller | skipping: Conditional result was False
2026-01-13 00:28:05.722053 | 
2026-01-13 00:28:05.722186 | PLAY [localhost]
2026-01-13 00:28:05.742292 | 
2026-01-13 00:28:05.742381 | TASK [Run Zuul manifest role]
2026-01-13 00:28:05.763982 | localhost | ok
2026-01-13 00:28:05.777998 | 
2026-01-13 00:28:05.778064 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-13 00:28:06.240320 | localhost | changed
2026-01-13 00:28:06.251257 | 
2026-01-13 00:28:06.251386 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-13 00:28:06.300987 | localhost | ok
2026-01-13 00:28:06.321331 | 
2026-01-13 00:28:06.321450 | TASK [Set zuul-log-path fact]
2026-01-13 00:28:06.397806 | localhost | ok
2026-01-13 00:28:06.415784 | 
2026-01-13 00:28:06.415893 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-13 00:28:06.460543 | localhost | ok
2026-01-13 00:28:06.477935 | 
2026-01-13 00:28:06.478014 | LOOP [Run upload-logs-swift role]
2026-01-13 00:28:06.523188 | localhost | Output suppressed because no_log was given
2026-01-13 00:28:06.562620 | 
2026-01-13 00:28:06.562814 | TASK [Set zuul-log-path fact]
2026-01-13 00:28:06.600024 | localhost | skipping: Conditional result was False
2026-01-13 00:28:06.609315 | 
2026-01-13 00:28:06.609403 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-13 00:28:07.082470 | localhost -> localhost | ok: Runtime: 0:00:00.010444
2026-01-13 00:28:07.089315 | 
2026-01-13 00:28:07.089384 | TASK [upload-logs-swift : Upload logs to swift]