2025-10-15 00:06:38.760425 | Job console starting...
2025-10-15 00:06:38.771214 | Updating repositories
2025-10-15 00:06:39.134950 | Preparing job workspace
2025-10-15 00:06:55.873057 | Running Ansible setup...
2025-10-15 00:07:04.495703 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-15 00:07:05.135968 | 
2025-10-15 00:07:05.136101 | PLAY [localhost]
2025-10-15 00:07:05.147513 | 
2025-10-15 00:07:05.147596 | TASK [Gathering Facts]
2025-10-15 00:07:06.169225 | localhost | ok
2025-10-15 00:07:06.189839 | 
2025-10-15 00:07:06.189972 | TASK [Setup log path fact]
2025-10-15 00:07:06.207905 | localhost | ok
2025-10-15 00:07:06.221404 | 
2025-10-15 00:07:06.221514 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-15 00:07:06.249111 | localhost | ok
2025-10-15 00:07:06.257249 | 
2025-10-15 00:07:06.257328 | TASK [emit-job-header : Print job information]
2025-10-15 00:07:06.317028 | # Job Information
2025-10-15 00:07:06.317232 | Ansible Version: 2.15.12
2025-10-15 00:07:06.317268 | Job: ansible-test-sanity-docker-milestone
2025-10-15 00:07:06.317289 | Pipeline: periodic
2025-10-15 00:07:06.317307 | Executor: ze04.softwarefactory-project.io
2025-10-15 00:07:06.317325 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-15 00:07:06.317345 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/de7/ansible/de7e781d2ec942da88f06f67cb2b2218/
2025-10-15 00:07:06.317363 | Event ID: ef49facc7688412789129926cf599d5c
2025-10-15 00:07:06.321500 | 
2025-10-15 00:07:06.321579 | LOOP [emit-job-header : Print node information]
2025-10-15 00:07:06.560191 | localhost | ok:
2025-10-15 00:07:06.560392 | localhost | # Node Information
2025-10-15 00:07:06.560419 | localhost | Inventory Hostname: controller
2025-10-15 00:07:06.560453 | localhost | Hostname: ip-172-16-211-182
2025-10-15 00:07:06.560474 | localhost | Username: zuul-worker
2025-10-15 00:07:06.560494 | localhost | Distro: Fedora 37
2025-10-15 00:07:06.560513 | localhost | Provider: ansible-us-east-2
2025-10-15 00:07:06.560531 | localhost | Region: us-east-2
2025-10-15 00:07:06.560548 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-15 00:07:06.560565 | localhost | Product Name: t3.small
2025-10-15 00:07:06.560582 | localhost | Interface IP: 3.139.91.215
2025-10-15 00:07:06.569376 | 
2025-10-15 00:07:06.569476 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-15 00:07:06.973439 | localhost -> localhost | changed
2025-10-15 00:07:06.978885 | 
2025-10-15 00:07:06.978970 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-15 00:07:08.483773 | localhost -> localhost | changed
2025-10-15 00:07:08.515624 | 
2025-10-15 00:07:08.515795 | PLAY [all:!appliance*]
2025-10-15 00:07:08.538818 | 
2025-10-15 00:07:08.538934 | TASK [include_role : start-zuul-console]
2025-10-15 00:07:08.559610 | controller | ok
2025-10-15 00:07:08.572780 | 
2025-10-15 00:07:08.572869 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-15 00:07:09.241344 | controller | ok
2025-10-15 00:07:09.271359 | 
2025-10-15 00:07:09.271538 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-15 00:07:10.866993 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-15 00:07:10.882493 | 
2025-10-15 00:07:10.882725 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-15 00:07:11.032933 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.047967 | 
2025-10-15 00:07:11.048196 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-15 00:07:11.076082 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.091283 | 
2025-10-15 00:07:11.091555 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-15 00:07:11.130307 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.144889 | 
2025-10-15 00:07:11.145093 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-15 00:07:11.173580 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.189635 | 
2025-10-15 00:07:11.190113 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-15 00:07:11.219593 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.235965 | 
2025-10-15 00:07:11.236453 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-15 00:07:11.264029 | controller | skipping: Conditional result was False
2025-10-15 00:07:11.285491 | 
2025-10-15 00:07:11.285729 | TASK [Disable Fedora Modular]
2025-10-15 00:07:11.996543 | controller | changed
2025-10-15 00:07:12.009730 | 
2025-10-15 00:07:12.009926 | TASK [Enable EPEL]
2025-10-15 00:07:12.049811 | controller | skipping: Conditional result was False
2025-10-15 00:07:12.066092 | 
2025-10-15 00:07:12.066255 | TASK [Register the RHEL node]
2025-10-15 00:07:12.232987 | 
2025-10-15 00:07:12.233258 | TASK [Show the subscription-manager status]
2025-10-15 00:07:12.430538 | controller | skipping: Conditional result was False
2025-10-15 00:07:12.440015 | 
2025-10-15 00:07:12.440110 | TASK [Enable EPEL on RHEL]
2025-10-15 00:07:12.587742 | controller | skipping: Conditional result was False
2025-10-15 00:07:12.597739 | 
2025-10-15 00:07:12.597836 | TASK [Install git and tox]
2025-10-15 00:08:29.429710 | controller | changed
2025-10-15 00:08:29.443998 | 
2025-10-15 00:08:29.444222 | TASK [include_role : prepare-workspace]
2025-10-15 00:08:29.480580 | controller | ok
2025-10-15 00:08:29.533346 | 
2025-10-15 00:08:29.533504 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-15 00:08:30.042564 | controller | ok
2025-10-15 00:08:30.078185 | 
2025-10-15 00:08:30.078398 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-15 00:08:46.918761 | controller | Output suppressed because no_log was given
2025-10-15 00:08:46.929400 | 
2025-10-15 00:08:46.929489 | TASK [include_role : prepare-workspace-openshift]
2025-10-15 00:08:46.953893 | controller | skipping: Conditional result was False
2025-10-15 00:08:46.979087 | 
2025-10-15 00:08:46.979174 | PLAY [all:!appliance]
2025-10-15 00:08:46.995747 | 
2025-10-15 00:08:46.995821 | TASK [Run add-build-sshkey role (RSA)]
2025-10-15 00:08:47.025765 | controller | ok
2025-10-15 00:08:47.040881 | 
2025-10-15 00:08:47.040978 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-15 00:08:47.308466 | controller -> localhost | ok
2025-10-15 00:08:47.315041 | 
2025-10-15 00:08:47.315121 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-15 00:08:47.347293 | controller | ok
2025-10-15 00:08:47.362375 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-15 00:08:47.368201 | 
2025-10-15 00:08:47.368266 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-15 00:08:47.861998 | controller -> localhost | Generating public/private rsa key pair.
2025-10-15 00:08:47.862217 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_rsa.
2025-10-15 00:08:47.862247 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_rsa.pub.
2025-10-15 00:08:47.862269 | controller -> localhost | The key fingerprint is:
2025-10-15 00:08:47.862288 | controller -> localhost | SHA256:Jii/DgYpey+uIlc6k6LoTzT/almWP7tCBbjbxsAJBSE zuul-build-sshkey
2025-10-15 00:08:47.862308 | controller -> localhost | The key's randomart image is:
2025-10-15 00:08:47.862326 | controller -> localhost | +---[RSA 2048]----+
2025-10-15 00:08:47.862345 | controller -> localhost | | E o+..          |
2025-10-15 00:08:47.862364 | controller -> localhost | |  .. . .         |
2025-10-15 00:08:47.862381 | controller -> localhost | |    o o .        |
2025-10-15 00:08:47.862399 | controller -> localhost | | .   *   .       |
2025-10-15 00:08:47.862417 | controller -> localhost | |+ .o. * S        |
2025-10-15 00:08:47.862446 | controller -> localhost | |.o.o+. @         |
2025-10-15 00:08:47.862470 | controller -> localhost | |. +=..* .        |
2025-10-15 00:08:47.862490 | controller -> localhost | |=oOo +.. o       |
2025-10-15 00:08:47.862509 | controller -> localhost | |O*o*=....o+      |
2025-10-15 00:08:47.862530 | controller -> localhost | +----[SHA256]-----+
2025-10-15 00:08:47.862582 | controller -> localhost | ok: Runtime: 0:00:00.075431
2025-10-15 00:08:47.869311 | 
2025-10-15 00:08:47.869376 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-15 00:08:47.901205 | controller | ok
2025-10-15 00:08:47.911804 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-15 00:08:47.920649 | 
2025-10-15 00:08:47.920737 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-15 00:08:47.945442 | controller | skipping: Conditional result was False
2025-10-15 00:08:47.952359 | 
2025-10-15 00:08:47.952441 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-15 00:08:48.596427 | controller | changed
2025-10-15 00:08:48.603163 | 
2025-10-15 00:08:48.603240 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-15 00:08:49.762055 | controller | ok
2025-10-15 00:08:49.777981 | 
2025-10-15 00:08:49.778183 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-15 00:08:51.588724 | controller | changed
2025-10-15 00:08:51.602587 | 
2025-10-15 00:08:51.602780 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-15 00:08:52.910877 | controller | changed
2025-10-15 00:08:52.924756 | 
2025-10-15 00:08:52.924902 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-15 00:08:52.954043 | controller | skipping: Conditional result was False
2025-10-15 00:08:52.960973 | 
2025-10-15 00:08:52.961188 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-15 00:08:53.405088 | controller -> localhost | changed
2025-10-15 00:08:53.426795 | 
2025-10-15 00:08:53.426929 | TASK [add-build-sshkey : Add back temp key]
2025-10-15 00:08:53.738495 | controller -> localhost | Identity added: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_rsa (zuul-build-sshkey)
2025-10-15 00:08:53.738745 | controller -> localhost | ok: Runtime: 0:00:00.009178
2025-10-15 00:08:53.744822 | 
2025-10-15 00:08:53.744885 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-15 00:08:54.233905 | controller | ok
2025-10-15 00:08:54.240947 | 
2025-10-15 00:08:54.241028 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-15 00:08:54.286256 | controller | skipping: Conditional result was False
2025-10-15 00:08:54.302159 | 
2025-10-15 00:08:54.302279 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-15 00:08:54.334196 | controller | ok
2025-10-15 00:08:54.354996 | 
2025-10-15 00:08:54.355105 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-15 00:08:54.635228 | controller -> localhost | ok
2025-10-15 00:08:54.641584 | 
2025-10-15 00:08:54.641674 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-15 00:08:54.672625 | controller | ok
2025-10-15 00:08:54.685120 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-15 00:08:54.701328 | 
2025-10-15 00:08:54.701448 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-15 00:08:54.952169 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-15 00:08:54.952356 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_ecdsa.
2025-10-15 00:08:54.952387 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_ecdsa.pub.
2025-10-15 00:08:54.952417 | controller -> localhost | The key fingerprint is:
2025-10-15 00:08:54.952438 | controller -> localhost | SHA256:m/y3aSF59TnMOTW+MUVhdcE/+JW45c1/ThvrCC18J9Q zuul-build-sshkey
2025-10-15 00:08:54.952461 | controller -> localhost | The key's randomart image is:
2025-10-15 00:08:54.952481 | controller -> localhost | +---[ECDSA 521]---+
2025-10-15 00:08:54.952500 | controller -> localhost | |              .+*|
2025-10-15 00:08:54.952542 | controller -> localhost | |              ..o|
2025-10-15 00:08:54.952562 | controller -> localhost | |              o.o|
2025-10-15 00:08:54.952582 | controller -> localhost | |             oo==|
2025-10-15 00:08:54.952605 | controller -> localhost | |        S  . oOEX|
2025-10-15 00:08:54.952623 | controller -> localhost | |       . o+ =. &+|
2025-10-15 00:08:54.952640 | controller -> localhost | |        +  * = oO|
2025-10-15 00:08:54.952658 | controller -> localhost | |         .  *.+o*|
2025-10-15 00:08:54.952704 | controller -> localhost | |          .ooo.=o|
2025-10-15 00:08:54.952733 | controller -> localhost | +----[SHA256]-----+
2025-10-15 00:08:54.952783 | controller -> localhost | ok: Runtime: 0:00:00.008548
2025-10-15 00:08:54.959266 | 
2025-10-15 00:08:54.959341 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-15 00:08:54.990705 | controller | ok
2025-10-15 00:08:54.998080 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-15 00:08:55.008515 | 
2025-10-15 00:08:55.008608 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-15 00:08:55.033168 | controller | skipping: Conditional result was False
2025-10-15 00:08:55.039464 | 
2025-10-15 00:08:55.039537 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-15 00:08:55.494548 | controller | changed
2025-10-15 00:08:55.505270 | 
2025-10-15 00:08:55.505373 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-15 00:08:55.851573 | controller | ok
2025-10-15 00:08:55.869301 | 
2025-10-15 00:08:55.869433 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-15 00:08:57.773632 | controller | changed
2025-10-15 00:08:57.785765 | 
2025-10-15 00:08:57.785918 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-15 00:08:59.150564 | controller | changed
2025-10-15 00:08:59.161163 | 
2025-10-15 00:08:59.161286 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-15 00:08:59.196575 | controller | skipping: Conditional result was False
2025-10-15 00:08:59.205263 | 
2025-10-15 00:08:59.205386 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-15 00:08:59.474745 | controller -> localhost | changed
2025-10-15 00:08:59.492237 | 
2025-10-15 00:08:59.492317 | TASK [add-build-sshkey : Add back temp key]
2025-10-15 00:08:59.812265 | controller -> localhost | Identity added: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/de7e781d2ec942da88f06f67cb2b2218_id_ecdsa (zuul-build-sshkey)
2025-10-15 00:08:59.812483 | controller -> localhost | ok: Runtime: 0:00:00.016309
2025-10-15 00:08:59.820273 | 
2025-10-15 00:08:59.820375 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-15 00:09:00.259341 | controller | ok
2025-10-15 00:09:00.266516 | 
2025-10-15 00:09:00.266603 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-15 00:09:00.302399 | controller | skipping: Conditional result was False
2025-10-15 00:09:00.317259 | 
2025-10-15 00:09:00.317358 | TASK [include_role : remove-zuul-sshkey]
2025-10-15 00:09:00.342786 | controller | skipping: Conditional result was False
2025-10-15 00:09:00.352022 | 
2025-10-15 00:09:00.352113 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-15 00:09:00.722672 | controller | ok: "logs"
2025-10-15 00:09:00.723009 | controller | ok: All items complete
2025-10-15 00:09:00.723049 | 
2025-10-15 00:09:01.013173 | controller | ok: "artifacts"
2025-10-15 00:09:01.665412 | controller | ok: "docs"
2025-10-15 00:09:01.692633 | 
2025-10-15 00:09:01.692965 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-15 00:09:02.498240 | controller | changed: "logs"
2025-10-15 00:09:03.156385 | controller | changed: "artifacts"
2025-10-15 00:09:03.600467 | controller | changed: "docs"
2025-10-15 00:09:03.659887 | 
2025-10-15 00:09:03.660002 | PLAY RECAP
2025-10-15 00:09:03.660062 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-15 00:09:03.660099 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-15 00:09:03.660124 | 
2025-10-15 00:09:03.786977 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-15 00:09:03.788853 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-15 00:09:04.464989 | 
2025-10-15 00:09:04.465146 | PLAY [all]
2025-10-15 00:09:04.490952 | 
2025-10-15 00:09:04.491108 | TASK [Install binary dependencies]
2025-10-15 00:09:04.587694 | controller | ok
2025-10-15 00:09:04.607552 | 
2025-10-15 00:09:04.607899 | TASK [bindep : Include find tasks]
2025-10-15 00:09:04.637129 | controller | ok
2025-10-15 00:09:04.645196 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-15 00:09:04.651903 | 
2025-10-15 00:09:04.651984 | TASK [bindep : Look for bindep.txt]
2025-10-15 00:09:05.223067 | controller | ok
2025-10-15 00:09:05.241393 | 
2025-10-15 00:09:05.241615 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:09:05.270652 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.277801 | 
2025-10-15 00:09:05.277888 | TASK [bindep : Look for other-requirements.txt]
2025-10-15 00:09:05.658747 | controller | ok
2025-10-15 00:09:05.664517 | 
2025-10-15 00:09:05.664603 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:09:05.703535 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.712511 | 
2025-10-15 00:09:05.712658 | TASK [bindep : Look for bindep fallback file]
2025-10-15 00:09:05.757768 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.769613 | 
2025-10-15 00:09:05.769892 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:09:05.796526 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.806603 | 
2025-10-15 00:09:05.806775 | TASK [bindep : Include bindep tasks]
2025-10-15 00:09:05.831970 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.839815 | 
2025-10-15 00:09:05.839956 | TASK [bindep : Include install tasks]
2025-10-15 00:09:05.864467 | controller | skipping: Conditional result was False
2025-10-15 00:09:05.872768 | 
2025-10-15 00:09:05.872910 | LOOP [bindep : Include package tasks]
2025-10-15 00:09:05.934098 | 
2025-10-15 00:09:05.934379 | TASK [Run test-setup role]
2025-10-15 00:09:05.956812 | controller | ok
2025-10-15 00:09:05.983738 | 
2025-10-15 00:09:05.983836 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-15 00:09:06.341936 | controller | ok
2025-10-15 00:09:06.352435 | 
2025-10-15 00:09:06.352531 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-15 00:09:06.492651 | controller | skipping: Conditional result was False
2025-10-15 00:09:06.519168 | 
2025-10-15 00:09:06.519272 | PLAY RECAP
2025-10-15 00:09:06.519313 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-15 00:09:06.519333 | 
2025-10-15 00:09:06.653551 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-15 00:09:06.654418 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-15 00:09:07.229969 | 
2025-10-15 00:09:07.230102 | PLAY [controller]
2025-10-15 00:09:07.251095 | 
2025-10-15 00:09:07.251199 | TASK [Create the /root directory]
2025-10-15 00:09:07.984115 | controller | ok
2025-10-15 00:09:07.989600 | 
2025-10-15 00:09:07.989671 | TASK [Install glibc-langpack-en]
2025-10-15 00:09:16.085479 | controller | ok: Nothing to do
2025-10-15 00:09:16.093222 | 
2025-10-15 00:09:16.093315 | TASK [Ensure controller directory exists]
2025-10-15 00:09:16.575006 | controller | changed
2025-10-15 00:09:16.580744 | 
2025-10-15 00:09:16.580814 | TASK [Install container runtime]
2025-10-15 00:09:16.658964 | controller | ok
2025-10-15 00:09:16.718584 | 
2025-10-15 00:09:16.718754 | LOOP [ensure-podman : Find distribution installation]
2025-10-15 00:09:16.744173 | controller | ok: "/var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-15 00:09:16.761723 | controller | included: /var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-15 00:09:16.768584 | 
2025-10-15 00:09:16.768698 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-15 00:10:33.860304 | controller | changed
2025-10-15 00:10:33.867022 | 
2025-10-15 00:10:33.867097 | TASK [ensure-podman : Fetch podman version]
2025-10-15 00:10:34.618010 | controller | Client:       Podman Engine
2025-10-15 00:10:34.645477 | controller | Version:      4.6.2
2025-10-15 00:10:34.645517 | controller | API Version:  4.6.2
2025-10-15 00:10:34.645524 | controller | Go Version:   go1.19.12
2025-10-15 00:10:34.645542 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-15 00:10:34.645549 | controller | OS/Arch:      linux/amd64
2025-10-15 00:10:35.009572 | controller | ok: Runtime: 0:00:00.219668
2025-10-15 00:10:35.019170 | 
2025-10-15 00:10:35.019273 | TASK [ensure-podman : Print podman version installed]
2025-10-15 00:10:35.052280 | Podman version: Client:       Podman Engine
2025-10-15 00:10:35.052506 | Version:      4.6.2
2025-10-15 00:10:35.052561 | API Version:  4.6.2
2025-10-15 00:10:35.052595 | Go Version:   go1.19.12
2025-10-15 00:10:35.052631 | Built:        Mon Aug 28 19:38:31 2023
2025-10-15 00:10:35.052667 | OS/Arch:      linux/amd64
2025-10-15 00:10:35.062745 | 
2025-10-15 00:10:35.062900 | TASK [ensure-podman : Validate podman engine]
2025-10-15 00:10:35.201461 | controller | skipping: Conditional result was False
2025-10-15 00:10:35.212459 | 
2025-10-15 00:10:35.212583 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-15 00:10:35.227488 | controller | skipping: Conditional result was False
2025-10-15 00:10:35.249183 | 
2025-10-15 00:10:35.249365 | TASK [Ensure python3.8 is present]
2025-10-15 00:10:35.265703 | controller | skipping: Conditional result was False
2025-10-15 00:10:35.277270 | 
2025-10-15 00:10:35.277423 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-15 00:10:35.299008 | controller | ok
2025-10-15 00:10:35.322699 | 
2025-10-15 00:10:35.322838 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-15 00:10:39.029840 | controller | ok: Nothing to do
2025-10-15 00:10:39.043387 | 
2025-10-15 00:10:39.043626 | TASK [our-ensure-python : Also install python3-devel]
2025-10-15 00:10:52.154927 | controller | changed
2025-10-15 00:10:52.166766 | 
2025-10-15 00:10:52.166877 | TASK [Run ensure-virtualenv role]
2025-10-15 00:10:52.187163 | controller | ok
2025-10-15 00:10:52.210589 | 
2025-10-15 00:10:52.210740 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-15 00:10:52.565617 | controller | /usr/bin/virtualenv
2025-10-15 00:10:52.849160 | controller | ok: Runtime: 0:00:00.004333
2025-10-15 00:10:52.856804 | 
2025-10-15 00:10:52.856925 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-15 00:10:52.883494 | controller | skipping: Conditional result was False
2025-10-15 00:10:52.883823 | controller | ok: All items complete
2025-10-15 00:10:52.883858 | 
2025-10-15 00:10:52.903850 | 
2025-10-15 00:10:52.903980 | TASK [Find the full path of the Python interpreter]
2025-10-15 00:10:53.824301 | controller | /usr/bin/python3
2025-10-15 00:10:54.074758 | controller | ok
2025-10-15 00:10:54.081407 | 
2025-10-15 00:10:54.081548 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-15 00:10:55.452995 | controller | created virtual environment CPython3.11.0.final.0-64 in 744ms
2025-10-15 00:10:55.493769 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-15 00:10:55.494498 | 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-15 00:10:55.494590 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-15 00:10:55.494614 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-15 00:10:55.724143 | controller | changed
2025-10-15 00:10:55.738978 | 
2025-10-15 00:10:55.739318 | TASK [Set selinux package]
2025-10-15 00:10:55.775536 | controller | ok
2025-10-15 00:10:55.782375 | 
2025-10-15 00:10:55.782473 | TASK [Set selinux package (Fedora)]
2025-10-15 00:10:55.841323 | controller | ok
2025-10-15 00:10:55.850391 | 
2025-10-15 00:10:55.850518 | TASK [Install selinux into virtualenv]
2025-10-15 00:10:58.430703 | controller | Collecting selinux-please-lie-to-me
2025-10-15 00:10:58.520620 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-15 00:10:59.043813 | controller | Collecting setuptools<50.0.0
2025-10-15 00:10:59.057421 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-15 00:10:59.131601 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.8 MB/s eta 0:00:00
2025-10-15 00:10:59.284051 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-15 00:10:59.284476 | controller |   Attempting uninstall: setuptools
2025-10-15 00:10:59.289401 | controller |     Found existing installation: setuptools 62.6.0
2025-10-15 00:10:59.401166 | controller |     Uninstalling setuptools-62.6.0:
2025-10-15 00:10:59.416364 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-15 00:11:00.164245 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-15 00:11:00.370462 | controller |
2025-10-15 00:11:00.589674 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-15 00:11:00.589726 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-15 00:11:01.009044 | controller | ok: Runtime: 0:00:04.267701
2025-10-15 00:11:01.014727 | 
2025-10-15 00:11:01.014815 | TASK [Install pytest-forked into virtualenv]
2025-10-15 00:11:02.273005 | controller | Collecting pytest-forked
2025-10-15 00:11:02.366861 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-15 00:11:02.425241 | controller | Collecting py
2025-10-15 00:11:02.444754 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-15 00:11:02.497301 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-10-15 00:11:02.787630 | controller | Collecting pytest>=3.10
2025-10-15 00:11:02.802239 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-15 00:11:02.871499 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-10-15 00:11:03.040364 | controller | Collecting iniconfig>=1
2025-10-15 00:11:03.058666 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-15 00:11:03.131397 | controller | Collecting packaging>=20
2025-10-15 00:11:03.146265 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-15 00:11:03.168690 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.0 MB/s eta 0:00:00
2025-10-15 00:11:03.250406 | controller | Collecting pluggy<2,>=1.5
2025-10-15 00:11:03.265050 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-15 00:11:03.342680 | controller | Collecting pygments>=2.7.2
2025-10-15 00:11:03.357419 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-15 00:11:03.460721 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 12.2 MB/s eta 0:00:00
2025-10-15 00:11:03.599123 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-15 00:11:05.863561 | controller | Successfully installed iniconfig-2.1.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-15 00:11:05.879707 | controller |
2025-10-15 00:11:06.068937 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-15 00:11:06.068985 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-15 00:11:06.169763 | controller | ok: Runtime: 0:00:04.589409
2025-10-15 00:11:06.182743 | 
2025-10-15 00:11:06.182872 | TASK [Update pip]
2025-10-15 00:11:07.323915 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-15 00:11:07.598062 | controller | Collecting pip
2025-10-15 00:11:07.704386 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-15 00:11:07.876627 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.6 MB/s eta 0:00:00
2025-10-15 00:11:08.040693 | controller | Installing collected packages: pip
2025-10-15 00:11:08.042294 | controller |   Attempting uninstall: pip
2025-10-15 00:11:08.047231 | controller |     Found existing installation: pip 22.2.2
2025-10-15 00:11:08.315087 | controller |     Uninstalling pip-22.2.2:
2025-10-15 00:11:08.345095 | controller |       Successfully uninstalled pip-22.2.2
2025-10-15 00:11:10.080918 | controller | Successfully installed pip-25.2
2025-10-15 00:11:10.348816 | controller | ok: Runtime: 0:00:03.543590
2025-10-15 00:11:10.362006 | 
2025-10-15 00:11:10.362173 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-15 00:11:10.870119 | controller | changed
2025-10-15 00:11:10.878111 | 
2025-10-15 00:11:10.878221 | TASK [Install ansible into virtualenv]
2025-10-15 00:11:11.932965 | controller | Processing ./src/github.com/ansible/ansible
2025-10-15 00:11:11.939472 | controller |   Installing build dependencies: started
2025-10-15 00:11:13.888971 | controller |   Installing build dependencies: finished with status 'done'
2025-10-15 00:11:15.400965 | controller |   Getting requirements to build wheel: started
2025-10-15 00:11:15.401033 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-15 00:11:16.318958 | controller |   Preparing metadata (pyproject.toml): started
2025-10-15 00:11:16.319014 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-15 00:11:16.322277 | 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-15 00:11:16.327181 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-15 00:11:16.540071 | controller | ERROR
2025-10-15 00:11:16.540349 | controller | {
2025-10-15 00:11:16.540412 | controller |   "delta": "0:00:05.165534",
2025-10-15 00:11:16.540456 | controller |   "end": "2025-10-15 00:11:16.476389",
2025-10-15 00:11:16.540496 | controller |   "msg": "non-zero return code",
2025-10-15 00:11:16.540550 | controller |   "rc": 1,
2025-10-15 00:11:16.540589 | controller |   "start": "2025-10-15 00:11:11.310855"
2025-10-15 00:11:16.540625 | controller | }
failure
2025-10-15 00:11:16.543753 | 
2025-10-15 00:11:16.543852 | PLAY RECAP
2025-10-15 00:11:16.543939 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-15 00:11:16.543986 | 
2025-10-15 00:11:16.684304 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-15 00:11:16.686444 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-15 00:11:17.308453 | 
2025-10-15 00:11:17.308581 | PLAY [all]
2025-10-15 00:11:17.332482 | 
2025-10-15 00:11:17.332649 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-15 00:11:18.132717 | controller | changed: non-zero return code
2025-10-15 00:11:18.139521 | 
2025-10-15 00:11:18.139657 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-15 00:11:18.154502 | controller | skipping: Conditional result was False
2025-10-15 00:11:18.161292 | 
2025-10-15 00:11:18.161391 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-15 00:11:18.182738 | 
2025-10-15 00:11:18.182901 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-15 00:11:18.213493 | 
2025-10-15 00:11:18.213661 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-15 00:11:18.238725 | controller | skipping: Conditional result was False
2025-10-15 00:11:18.248117 | 
2025-10-15 00:11:18.248225 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-15 00:11:18.301007 | 
2025-10-15 00:11:18.301379 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-15 00:11:18.327862 | controller | skipping: Conditional result was False
2025-10-15 00:11:18.336757 | 
2025-10-15 00:11:18.336878 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-15 00:11:18.362084 | controller | skipping: Conditional result was False
2025-10-15 00:11:18.370787 | 
2025-10-15 00:11:18.370919 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-15 00:11:18.396030 | controller | skipping: Conditional result was False
2025-10-15 00:11:18.433222 | 
2025-10-15 00:11:18.433345 | PLAY RECAP
2025-10-15 00:11:18.433403 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-15 00:11:18.433431 | 
2025-10-15 00:11:18.528674 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-15 00:11:18.529937 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-15 00:11:19.196355 | 
2025-10-15 00:11:19.196492 | PLAY [all:!appliance*]
2025-10-15 00:11:19.221344 | 
2025-10-15 00:11:19.221481 | TASK [unregister the node]
2025-10-15 00:11:19.364895 | controller | skipping: Conditional result was False
2025-10-15 00:11:19.378108 | 
2025-10-15 00:11:19.378346 | TASK [include_role : fetch-output]
2025-10-15 00:11:19.428326 | controller | ok
2025-10-15 00:11:19.464439 | 
2025-10-15 00:11:19.464583 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-15 00:11:19.540578 | controller | skipping: Conditional result was False
2025-10-15 00:11:19.548552 | 
2025-10-15 00:11:19.548673 | TASK [fetch-output : Set log path for single node]
2025-10-15 00:11:19.594559 | controller | ok
2025-10-15 00:11:19.606084 | 
2025-10-15 00:11:19.606252 | LOOP [fetch-output : Ensure local output dirs]
2025-10-15 00:11:20.019610 | controller -> localhost | ok: "/var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/logs"
2025-10-15 00:11:20.265027 | controller -> localhost | changed: "/var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/artifacts"
2025-10-15 00:11:20.521976 | controller -> localhost | changed: "/var/lib/zuul/builds/de7e781d2ec942da88f06f67cb2b2218/work/docs"
2025-10-15 00:11:20.531008 | 
2025-10-15 00:11:20.531110 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-15 00:11:21.734427 | controller | changed:
2025-10-15 00:11:21.734831 | controller | .d..t...... ./
2025-10-15 00:11:21.734910 | controller | cd+++++++++ controller/
2025-10-15 00:11:21.735005 | controller | changed: All items complete
2025-10-15 00:11:21.735057 | 
2025-10-15 00:11:22.822662 | controller | changed: .d..t...... ./
2025-10-15 00:11:23.882402 | controller | changed: .d..t...... ./
2025-10-15 00:11:23.923505 | 
2025-10-15 00:11:23.923744 | TASK [include_role : fetch-output-openshift]
2025-10-15 00:11:23.941360 | controller | skipping: Conditional result was False
2025-10-15 00:11:23.950567 | 
2025-10-15 00:11:23.950745 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-15 00:11:23.990313 | controller | skipping: Conditional result was False
2025-10-15 00:11:24.003889 | controller | skipping: Conditional result was False
2025-10-15 00:11:24.060185 | 
2025-10-15 00:11:24.060531 | PLAY [localhost]
2025-10-15 00:11:24.073247 | 
2025-10-15 00:11:24.073352 | TASK [Run Zuul manifest role]
2025-10-15 00:11:24.091364 | localhost | ok
2025-10-15 00:11:24.105861 | 
2025-10-15 00:11:24.105991 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-15 00:11:24.491699 | localhost | changed
2025-10-15 00:11:24.496311 | 
2025-10-15 00:11:24.496376 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-15 00:11:24.551950 | localhost | ok
2025-10-15 00:11:24.567172 | 
2025-10-15 00:11:24.567321 | TASK [Set zuul-log-path fact]
2025-10-15 00:11:24.590773 | localhost | ok
2025-10-15 00:11:24.614267 | 
2025-10-15 00:11:24.614399 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-15 00:11:24.642838 | localhost | ok
2025-10-15 00:11:24.652785 | 
2025-10-15 00:11:24.652926 | LOOP [Run upload-logs-swift role]
2025-10-15 00:11:24.688358 | localhost | Output suppressed because no_log was given
2025-10-15 00:11:24.714001 | 
2025-10-15 00:11:24.714112 | TASK [Set zuul-log-path fact]
2025-10-15 00:11:24.738739 | localhost | skipping: Conditional result was False
2025-10-15 00:11:24.744166 | 
2025-10-15 00:11:24.744250 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-15 00:11:25.229533 | localhost -> localhost | ok: Runtime: 0:00:00.024269
2025-10-15 00:11:25.236953 | 
2025-10-15 00:11:25.237066 | TASK [upload-logs-swift : Upload logs to swift]