2025-09-30 00:07:46.731050 | Job console starting...
2025-09-30 00:07:46.740641 | Updating repositories
2025-09-30 00:07:47.764518 | Preparing job workspace
2025-09-30 00:07:52.176436 | Running Ansible setup...
2025-09-30 00:07:58.109835 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-30 00:07:58.766930 | 
2025-09-30 00:07:58.767077 | PLAY [localhost]
2025-09-30 00:07:58.775959 | 
2025-09-30 00:07:58.776051 | TASK [Gathering Facts]
2025-09-30 00:07:59.834191 | localhost | ok
2025-09-30 00:07:59.856697 | 
2025-09-30 00:07:59.856842 | TASK [Setup log path fact]
2025-09-30 00:07:59.881001 | localhost | ok
2025-09-30 00:07:59.898744 | 
2025-09-30 00:07:59.898876 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 00:07:59.940033 | localhost | ok
2025-09-30 00:07:59.953669 | 
2025-09-30 00:07:59.953804 | TASK [emit-job-header : Print job information]
2025-09-30 00:08:00.007304 | # Job Information
2025-09-30 00:08:00.007516 | Ansible Version: 2.15.12
2025-09-30 00:08:00.007565 | Job: ansible-test-sanity-docker-devel
2025-09-30 00:08:00.007597 | Pipeline: periodic
2025-09-30 00:08:00.007625 | Executor: ze04.softwarefactory-project.io
2025-09-30 00:08:00.007653 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-30 00:08:00.007720 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/26f/ansible/26f7cead98fb4dcda6fafed61394c131/
2025-09-30 00:08:00.007753 | Event ID: 8b4cd1603b324f4bbcbe8377ef9bcb18
2025-09-30 00:08:00.013592 | 
2025-09-30 00:08:00.013714 | LOOP [emit-job-header : Print node information]
2025-09-30 00:08:00.132272 | localhost | ok:
2025-09-30 00:08:00.132436 | localhost | # Node Information
2025-09-30 00:08:00.132466 | localhost | Inventory Hostname: controller
2025-09-30 00:08:00.132486 | localhost | Hostname: ip-172-16-3-255
2025-09-30 00:08:00.132506 | localhost | Username: zuul-worker
2025-09-30 00:08:00.132527 | localhost | Distro: Fedora 37
2025-09-30 00:08:00.132545 | localhost | Provider: ansible-us-east-2
2025-09-30 00:08:00.132563 | localhost | Region: us-east-2
2025-09-30 00:08:00.132580 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-30 00:08:00.132598 | localhost | Product Name: t3.small
2025-09-30 00:08:00.132615 | localhost | Interface IP: 13.58.249.138
2025-09-30 00:08:00.157635 | 
2025-09-30 00:08:00.157857 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 00:08:00.563076 | localhost -> localhost | changed
2025-09-30 00:08:00.570646 | 
2025-09-30 00:08:00.570742 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 00:08:01.513881 | localhost -> localhost | changed
2025-09-30 00:08:01.560304 | 
2025-09-30 00:08:01.560538 | PLAY [all:!appliance*]
2025-09-30 00:08:01.585384 | 
2025-09-30 00:08:01.585500 | TASK [include_role : start-zuul-console]
2025-09-30 00:08:01.607934 | controller | ok
2025-09-30 00:08:01.628930 | 
2025-09-30 00:08:01.629037 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 00:08:03.264130 | controller | ok
2025-09-30 00:08:03.288147 | 
2025-09-30 00:08:03.288261 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-30 00:08:05.026218 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-30 00:08:05.041357 | 
2025-09-30 00:08:05.041499 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-30 00:08:05.424818 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.440370 | 
2025-09-30 00:08:05.440576 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-30 00:08:05.479074 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.489097 | 
2025-09-30 00:08:05.489204 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-30 00:08:05.514207 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.526049 | 
2025-09-30 00:08:05.526334 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-30 00:08:05.553168 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.564646 | 
2025-09-30 00:08:05.564839 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-30 00:08:05.582484 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.593080 | 
2025-09-30 00:08:05.593230 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-30 00:08:05.608921 | controller | skipping: Conditional result was False
2025-09-30 00:08:05.625712 | 
2025-09-30 00:08:05.625865 | TASK [Disable Fedora Modular]
2025-09-30 00:08:06.352256 | controller | changed
2025-09-30 00:08:06.360292 | 
2025-09-30 00:08:06.360383 | TASK [Enable EPEL]
2025-09-30 00:08:06.386468 | controller | skipping: Conditional result was False
2025-09-30 00:08:06.400515 | 
2025-09-30 00:08:06.400673 | TASK [Register the RHEL node]
2025-09-30 00:08:06.553364 | 
2025-09-30 00:08:06.553556 | TASK [Show the subscription-manager status]
2025-09-30 00:08:06.723982 | controller | skipping: Conditional result was False
2025-09-30 00:08:06.733555 | 
2025-09-30 00:08:06.733663 | TASK [Enable EPEL on RHEL]
2025-09-30 00:08:06.881205 | controller | skipping: Conditional result was False
2025-09-30 00:08:06.897280 | 
2025-09-30 00:08:06.897467 | TASK [Install git and tox]
2025-09-30 00:09:43.357302 | controller | changed
2025-09-30 00:09:43.370651 | 
2025-09-30 00:09:43.370818 | TASK [include_role : prepare-workspace]
2025-09-30 00:09:43.409233 | controller | ok
2025-09-30 00:09:43.446919 | 
2025-09-30 00:09:43.447067 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 00:09:44.161191 | controller | ok
2025-09-30 00:09:44.167789 | 
2025-09-30 00:09:44.167866 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 00:10:08.080603 | controller | Output suppressed because no_log was given
2025-09-30 00:10:08.096412 | 
2025-09-30 00:10:08.096542 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 00:10:08.116414 | controller | skipping: Conditional result was False
2025-09-30 00:10:08.148905 | 
2025-09-30 00:10:08.149008 | PLAY [all:!appliance]
2025-09-30 00:10:08.193116 | 
2025-09-30 00:10:08.193233 | TASK [Run add-build-sshkey role (RSA)]
2025-09-30 00:10:08.223410 | controller | ok
2025-09-30 00:10:08.239146 | 
2025-09-30 00:10:08.239256 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 00:10:08.476806 | controller -> localhost | ok
2025-09-30 00:10:08.483953 | 
2025-09-30 00:10:08.484026 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 00:10:08.503177 | controller | ok
2025-09-30 00:10:08.517560 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 00:10:08.523534 | 
2025-09-30 00:10:08.523594 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 00:10:08.983619 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 00:10:08.983833 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_rsa.
2025-09-30 00:10:08.983867 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_rsa.pub.
2025-09-30 00:10:08.983892 | controller -> localhost | The key fingerprint is:
2025-09-30 00:10:08.983915 | controller -> localhost | SHA256:N7a4WIEuNxGAvc5ZC0881P5w86J3K4NrctZuHkMVS1I zuul-build-sshkey
2025-09-30 00:10:08.983939 | controller -> localhost | The key's randomart image is:
2025-09-30 00:10:08.983960 | controller -> localhost | +---[RSA 2048]----+
2025-09-30 00:10:08.983982 | controller -> localhost | |   o.  .  ..E    |
2025-09-30 00:10:08.984004 | controller -> localhost | |  . ... .  o o   |
2025-09-30 00:10:08.984025 | controller -> localhost | |     +..    o    |
2025-09-30 00:10:08.984047 | controller -> localhost | |    o =oo o.     |
2025-09-30 00:10:08.984068 | controller -> localhost | |   o *ooS+=o     |
2025-09-30 00:10:08.984100 | controller -> localhost | |    +.o. *oo.    |
2025-09-30 00:10:08.984125 | controller -> localhost | |    . + o++.     |
2025-09-30 00:10:08.984146 | controller -> localhost | |     o.+*.*o.    |
2025-09-30 00:10:08.984168 | controller -> localhost | |      .=o*o+..   |
2025-09-30 00:10:08.984190 | controller -> localhost | +----[SHA256]-----+
2025-09-30 00:10:08.984245 | controller -> localhost | ok: Runtime: 0:00:00.122367
2025-09-30 00:10:08.990787 | 
2025-09-30 00:10:08.990850 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 00:10:09.013006 | controller | ok
2025-09-30 00:10:09.023110 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 00:10:09.031760 | 
2025-09-30 00:10:09.031899 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 00:10:09.046902 | controller | skipping: Conditional result was False
2025-09-30 00:10:09.054872 | 
2025-09-30 00:10:09.054971 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 00:10:09.762408 | controller | changed
2025-09-30 00:10:09.775318 | 
2025-09-30 00:10:09.775458 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 00:10:10.209097 | controller | ok
2025-09-30 00:10:10.217054 | 
2025-09-30 00:10:10.217143 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 00:10:12.070025 | controller | changed
2025-09-30 00:10:12.081244 | 
2025-09-30 00:10:12.081381 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 00:10:13.458665 | controller | changed
2025-09-30 00:10:13.471604 | 
2025-09-30 00:10:13.471772 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 00:10:13.501765 | controller | skipping: Conditional result was False
2025-09-30 00:10:13.517585 | 
2025-09-30 00:10:13.517775 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 00:10:13.944959 | controller -> localhost | changed
2025-09-30 00:10:13.957306 | 
2025-09-30 00:10:13.957418 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 00:10:14.218142 | controller -> localhost | Identity added: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_rsa (zuul-build-sshkey)
2025-09-30 00:10:14.218602 | controller -> localhost | ok: Runtime: 0:00:00.008199
2025-09-30 00:10:14.234037 | 
2025-09-30 00:10:14.234196 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 00:10:14.754662 | controller | ok
2025-09-30 00:10:14.767610 | 
2025-09-30 00:10:14.767816 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 00:10:14.816607 | controller | skipping: Conditional result was False
2025-09-30 00:10:14.845718 | 
2025-09-30 00:10:14.845886 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-30 00:10:14.881098 | controller | ok
2025-09-30 00:10:14.903320 | 
2025-09-30 00:10:14.903411 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 00:10:15.192992 | controller -> localhost | ok
2025-09-30 00:10:15.208260 | 
2025-09-30 00:10:15.208420 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 00:10:15.249371 | controller | ok
2025-09-30 00:10:15.279791 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 00:10:15.295916 | 
2025-09-30 00:10:15.296086 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 00:10:15.639672 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-30 00:10:15.639919 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_ecdsa.
2025-09-30 00:10:15.639948 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_ecdsa.pub.
2025-09-30 00:10:15.639983 | controller -> localhost | The key fingerprint is:
2025-09-30 00:10:15.640004 | controller -> localhost | SHA256:MDiyewlxBm9U6IREC189YMhCd0xfMBRzgj+/343GwwA zuul-build-sshkey
2025-09-30 00:10:15.640023 | controller -> localhost | The key's randomart image is:
2025-09-30 00:10:15.640041 | controller -> localhost | +---[ECDSA 521]---+
2025-09-30 00:10:15.640059 | controller -> localhost | |o=++BB+Boo       |
2025-09-30 00:10:15.640077 | controller -> localhost | |.o=B+++ *        |
2025-09-30 00:10:15.640094 | controller -> localhost | | .=oB +o         |
2025-09-30 00:10:15.640111 | controller -> localhost | |   B.. = E       |
2025-09-30 00:10:15.640128 | controller -> localhost | |  o     S .      |
2025-09-30 00:10:15.640145 | controller -> localhost | |   o .   . .     |
2025-09-30 00:10:15.640162 | controller -> localhost | |  . o     . +    |
2025-09-30 00:10:15.640179 | controller -> localhost | |   .     .  .=o  |
2025-09-30 00:10:15.640195 | controller -> localhost | |          ...o.. |
2025-09-30 00:10:15.640212 | controller -> localhost | +----[SHA256]-----+
2025-09-30 00:10:15.640268 | controller -> localhost | ok: Runtime: 0:00:00.016066
2025-09-30 00:10:15.646756 | 
2025-09-30 00:10:15.646845 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 00:10:15.666163 | controller | ok
2025-09-30 00:10:15.673401 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 00:10:15.681940 | 
2025-09-30 00:10:15.682003 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 00:10:15.705995 | controller | skipping: Conditional result was False
2025-09-30 00:10:15.714279 | 
2025-09-30 00:10:15.714378 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 00:10:16.190778 | controller | changed
2025-09-30 00:10:16.203660 | 
2025-09-30 00:10:16.203860 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 00:10:16.581505 | controller | ok
2025-09-30 00:10:16.596955 | 
2025-09-30 00:10:16.597125 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 00:10:18.210943 | controller | changed
2025-09-30 00:10:18.218988 | 
2025-09-30 00:10:18.219075 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 00:10:19.618330 | controller | changed
2025-09-30 00:10:19.632951 | 
2025-09-30 00:10:19.633159 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 00:10:19.663945 | controller | skipping: Conditional result was False
2025-09-30 00:10:19.687264 | 
2025-09-30 00:10:19.687441 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 00:10:19.940723 | controller -> localhost | changed
2025-09-30 00:10:19.955755 | 
2025-09-30 00:10:19.955926 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 00:10:20.267041 | controller -> localhost | Identity added: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/26f7cead98fb4dcda6fafed61394c131_id_ecdsa (zuul-build-sshkey)
2025-09-30 00:10:20.267406 | controller -> localhost | ok: Runtime: 0:00:00.014004
2025-09-30 00:10:20.281190 | 
2025-09-30 00:10:20.281383 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 00:10:20.769603 | controller | ok
2025-09-30 00:10:20.778860 | 
2025-09-30 00:10:20.779016 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 00:10:20.815891 | controller | skipping: Conditional result was False
2025-09-30 00:10:20.845744 | 
2025-09-30 00:10:20.845957 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 00:10:20.872391 | controller | skipping: Conditional result was False
2025-09-30 00:10:20.882455 | 
2025-09-30 00:10:20.882594 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 00:10:21.270866 | controller | ok: "logs"
2025-09-30 00:10:21.271222 | controller | ok: All items complete
2025-09-30 00:10:21.271265 | 
2025-09-30 00:10:21.567159 | controller | ok: "artifacts"
2025-09-30 00:10:21.857328 | controller | ok: "docs"
2025-09-30 00:10:21.874563 | 
2025-09-30 00:10:21.874816 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 00:10:22.243575 | controller | changed: "logs"
2025-09-30 00:10:22.566551 | controller | changed: "artifacts"
2025-09-30 00:10:22.874479 | controller | changed: "docs"
2025-09-30 00:10:22.914960 | 
2025-09-30 00:10:22.915097 | PLAY RECAP
2025-09-30 00:10:22.915159 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-30 00:10:22.915195 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 00:10:22.915221 | 
2025-09-30 00:10:23.069601 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-30 00:10:23.071345 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 00:10:23.684378 | 
2025-09-30 00:10:23.684490 | PLAY [all]
2025-09-30 00:10:23.706303 | 
2025-09-30 00:10:23.706411 | TASK [Install binary dependencies]
2025-09-30 00:10:23.785973 | controller | ok
2025-09-30 00:10:23.805174 | 
2025-09-30 00:10:23.805263 | TASK [bindep : Include find tasks]
2025-09-30 00:10:23.845289 | controller | ok
2025-09-30 00:10:23.853335 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-30 00:10:23.859304 | 
2025-09-30 00:10:23.859377 | TASK [bindep : Look for bindep.txt]
2025-09-30 00:10:24.424337 | controller | ok
2025-09-30 00:10:24.431113 | 
2025-09-30 00:10:24.431193 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:10:24.455772 | controller | skipping: Conditional result was False
2025-09-30 00:10:24.467002 | 
2025-09-30 00:10:24.467127 | TASK [bindep : Look for other-requirements.txt]
2025-09-30 00:10:24.800141 | controller | ok
2025-09-30 00:10:24.806447 | 
2025-09-30 00:10:24.806540 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:10:24.841599 | controller | skipping: Conditional result was False
2025-09-30 00:10:24.851497 | 
2025-09-30 00:10:24.851606 | TASK [bindep : Look for bindep fallback file]
2025-09-30 00:10:24.899047 | controller | skipping: Conditional result was False
2025-09-30 00:10:24.907939 | 
2025-09-30 00:10:24.908039 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:10:24.935271 | controller | skipping: Conditional result was False
2025-09-30 00:10:24.944440 | 
2025-09-30 00:10:24.944543 | TASK [bindep : Include bindep tasks]
2025-09-30 00:10:24.982131 | controller | skipping: Conditional result was False
2025-09-30 00:10:24.992507 | 
2025-09-30 00:10:24.992602 | TASK [bindep : Include install tasks]
2025-09-30 00:10:25.029445 | controller | skipping: Conditional result was False
2025-09-30 00:10:25.041596 | 
2025-09-30 00:10:25.041735 | LOOP [bindep : Include package tasks]
2025-09-30 00:10:25.113621 | 
2025-09-30 00:10:25.113881 | TASK [Run test-setup role]
2025-09-30 00:10:25.136532 | controller | ok
2025-09-30 00:10:25.163134 | 
2025-09-30 00:10:25.163268 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-30 00:10:25.476786 | controller | ok
2025-09-30 00:10:25.491732 | 
2025-09-30 00:10:25.491937 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-30 00:10:25.647527 | controller | skipping: Conditional result was False
2025-09-30 00:10:25.701422 | 
2025-09-30 00:10:25.701537 | PLAY RECAP
2025-09-30 00:10:25.701596 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 00:10:25.701661 | 
2025-09-30 00:10:25.822788 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 00:10:25.824556 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-30 00:10:26.475608 | 
2025-09-30 00:10:26.475753 | PLAY [controller]
2025-09-30 00:10:26.494821 | 
2025-09-30 00:10:26.494899 | TASK [Create the /root directory]
2025-09-30 00:10:27.283893 | controller | ok
2025-09-30 00:10:27.296861 | 
2025-09-30 00:10:27.297045 | TASK [Install glibc-langpack-en]
2025-09-30 00:10:35.469233 | controller | ok: Nothing to do
2025-09-30 00:10:35.483439 | 
2025-09-30 00:10:35.483602 | TASK [Ensure controller directory exists]
2025-09-30 00:10:35.916206 | controller | changed
2025-09-30 00:10:35.922123 | 
2025-09-30 00:10:35.922191 | TASK [Install container runtime]
2025-09-30 00:10:35.998645 | controller | ok
2025-09-30 00:10:36.059137 | 
2025-09-30 00:10:36.059291 | LOOP [ensure-podman : Find distribution installation]
2025-09-30 00:10:36.084915 | controller | ok: "/var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-30 00:10:36.102125 | controller | included: /var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-30 00:10:36.117773 | 
2025-09-30 00:10:36.117917 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-30 00:11:57.673315 | controller | changed
2025-09-30 00:11:57.681372 | 
2025-09-30 00:11:57.681451 | TASK [ensure-podman : Fetch podman version]
2025-09-30 00:11:58.503545 | controller | Client:       Podman Engine
2025-09-30 00:11:58.503625 | controller | Version:      4.6.2
2025-09-30 00:11:58.503655 | controller | API Version:  4.6.2
2025-09-30 00:11:58.503681 | controller | Go Version:   go1.19.12
2025-09-30 00:11:58.503720 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-30 00:11:58.503748 | controller | OS/Arch:      linux/amd64
2025-09-30 00:11:58.820804 | controller | ok: Runtime: 0:00:00.241622
2025-09-30 00:11:58.835163 | 
2025-09-30 00:11:58.835336 | TASK [ensure-podman : Print podman version installed]
2025-09-30 00:11:58.875576 | Podman version: Client:       Podman Engine
2025-09-30 00:11:58.875929 | Version:      4.6.2
2025-09-30 00:11:58.876017 | API Version:  4.6.2
2025-09-30 00:11:58.876085 | Go Version:   go1.19.12
2025-09-30 00:11:58.876146 | Built:        Mon Aug 28 19:38:31 2023
2025-09-30 00:11:58.876208 | OS/Arch:      linux/amd64
2025-09-30 00:11:58.889918 | 
2025-09-30 00:11:58.890070 | TASK [ensure-podman : Validate podman engine]
2025-09-30 00:11:59.034244 | controller | skipping: Conditional result was False
2025-09-30 00:11:59.047973 | 
2025-09-30 00:11:59.048114 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-30 00:11:59.075806 | controller | skipping: Conditional result was False
2025-09-30 00:11:59.104504 | 
2025-09-30 00:11:59.104722 | TASK [Ensure python3.8 is present]
2025-09-30 00:11:59.131788 | controller | skipping: Conditional result was False
2025-09-30 00:11:59.145081 | 
2025-09-30 00:11:59.145222 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-30 00:11:59.174851 | controller | ok
2025-09-30 00:11:59.215704 | 
2025-09-30 00:11:59.215855 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-30 00:12:03.479066 | controller | ok: Nothing to do
2025-09-30 00:12:03.490888 | 
2025-09-30 00:12:03.491020 | TASK [our-ensure-python : Also install python3-devel]
2025-09-30 00:12:16.895549 | controller | changed
2025-09-30 00:12:16.912034 | 
2025-09-30 00:12:16.912138 | TASK [Run ensure-virtualenv role]
2025-09-30 00:12:16.934871 | controller | ok
2025-09-30 00:12:16.968855 | 
2025-09-30 00:12:16.969109 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-30 00:12:17.366873 | controller | /usr/bin/virtualenv
2025-09-30 00:12:17.602899 | controller | ok: Runtime: 0:00:00.004736
2025-09-30 00:12:17.611443 | 
2025-09-30 00:12:17.611526 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-30 00:12:17.645130 | controller | skipping: Conditional result was False
2025-09-30 00:12:17.645364 | controller | ok: All items complete
2025-09-30 00:12:17.645393 | 
2025-09-30 00:12:17.662575 | 
2025-09-30 00:12:17.662723 | TASK [Find the full path of the Python interpreter]
2025-09-30 00:12:18.114578 | controller | /usr/bin/python3
2025-09-30 00:12:18.301722 | controller | ok
2025-09-30 00:12:18.318063 | 
2025-09-30 00:12:18.318266 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-30 00:12:19.805460 | controller | created virtual environment CPython3.11.0.final.0-64 in 754ms
2025-09-30 00:12:19.864777 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-30 00:12:19.864831 | 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-09-30 00:12:19.864847 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-30 00:12:19.864869 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-30 00:12:19.990622 | controller | changed
2025-09-30 00:12:19.996977 | 
2025-09-30 00:12:19.997051 | TASK [Set selinux package]
2025-09-30 00:12:20.039275 | controller | ok
2025-09-30 00:12:20.045615 | 
2025-09-30 00:12:20.045693 | TASK [Set selinux package (Fedora)]
2025-09-30 00:12:20.136006 | controller | ok
2025-09-30 00:12:20.143624 | 
2025-09-30 00:12:20.143862 | TASK [Install selinux into virtualenv]
2025-09-30 00:12:22.755125 | controller | Collecting selinux-please-lie-to-me
2025-09-30 00:12:22.843483 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-30 00:12:23.366917 | controller | Collecting setuptools<50.0.0
2025-09-30 00:12:23.383231 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-30 00:12:23.507299 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.7 MB/s eta 0:00:00
2025-09-30 00:12:23.660715 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-30 00:12:23.661118 | controller |   Attempting uninstall: setuptools
2025-09-30 00:12:23.666050 | controller |     Found existing installation: setuptools 62.6.0
2025-09-30 00:12:23.776823 | controller |     Uninstalling setuptools-62.6.0:
2025-09-30 00:12:23.792276 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-30 00:12:24.548734 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-30 00:12:24.750321 | controller |
2025-09-30 00:12:24.965700 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-30 00:12:24.965749 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-30 00:12:25.356786 | controller | ok: Runtime: 0:00:04.325612
2025-09-30 00:12:25.362882 | 
2025-09-30 00:12:25.362948 | TASK [Install pytest-forked into virtualenv]
2025-09-30 00:12:26.554971 | controller | Collecting pytest-forked
2025-09-30 00:12:26.644147 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-30 00:12:26.704109 | controller | Collecting py
2025-09-30 00:12:26.718514 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-30 00:12:26.755581 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-09-30 00:12:26.924996 | controller | Collecting pytest>=3.10
2025-09-30 00:12:26.938286 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-30 00:12:27.004703 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.7 MB/s eta 0:00:00
2025-09-30 00:12:27.059075 | controller | Collecting iniconfig>=1
2025-09-30 00:12:27.072855 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-30 00:12:27.137908 | controller | Collecting packaging>=20
2025-09-30 00:12:27.151085 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-30 00:12:27.162787 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.9 MB/s eta 0:00:00
2025-09-30 00:12:27.206861 | controller | Collecting pluggy<2,>=1.5
2025-09-30 00:12:27.220653 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-30 00:12:27.293657 | controller | Collecting pygments>=2.7.2
2025-09-30 00:12:27.306502 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-30 00:12:27.435810 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.7 MB/s eta 0:00:00
2025-09-30 00:12:27.568448 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-30 00:12:29.791283 | 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-09-30 00:12:29.807330 | controller |
2025-09-30 00:12:29.991117 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-30 00:12:29.991169 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-30 00:12:30.500413 | controller | ok: Runtime: 0:00:04.158781
2025-09-30 00:12:30.507321 | 
2025-09-30 00:12:30.507385 | TASK [Update pip]
2025-09-30 00:12:31.620752 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-30 00:12:31.895706 | controller | Collecting pip
2025-09-30 00:12:31.994773 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-30 00:12:32.178390 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.9 MB/s eta 0:00:00
2025-09-30 00:12:32.356186 | controller | Installing collected packages: pip
2025-09-30 00:12:32.356617 | controller |   Attempting uninstall: pip
2025-09-30 00:12:32.361084 | controller |     Found existing installation: pip 22.2.2
2025-09-30 00:12:32.684834 | controller |     Uninstalling pip-22.2.2:
2025-09-30 00:12:32.721530 | controller |       Successfully uninstalled pip-22.2.2
2025-09-30 00:12:34.466634 | controller | Successfully installed pip-25.2
2025-09-30 00:12:35.142984 | controller | ok: Runtime: 0:00:03.647135
2025-09-30 00:12:35.151260 | 
2025-09-30 00:12:35.151366 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-30 00:12:35.662137 | controller | changed
2025-09-30 00:12:35.668960 | 
2025-09-30 00:12:35.669033 | TASK [Install ansible into virtualenv]
2025-09-30 00:12:36.718523 | controller | Processing ./src/github.com/ansible/ansible
2025-09-30 00:12:36.725090 | controller |   Installing build dependencies: started
2025-09-30 00:12:38.598428 | controller |   Installing build dependencies: finished with status 'done'
2025-09-30 00:12:38.598643 | controller |   Getting requirements to build wheel: started
2025-09-30 00:12:40.121187 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-30 00:12:40.122631 | controller |   Preparing metadata (pyproject.toml): started
2025-09-30 00:12:41.046425 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-30 00:12:41.051100 | 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-09-30 00:12:41.056016 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-30 00:12:41.306821 | controller | ERROR
2025-09-30 00:12:41.306996 | controller | {
2025-09-30 00:12:41.307026 | controller |   "delta": "0:00:05.116097",
2025-09-30 00:12:41.307045 | controller |   "end": "2025-09-30 00:12:41.209876",
2025-09-30 00:12:41.307064 | controller |   "msg": "non-zero return code",
2025-09-30 00:12:41.307090 | controller |   "rc": 1,
2025-09-30 00:12:41.307107 | controller |   "start": "2025-09-30 00:12:36.093779"
2025-09-30 00:12:41.307122 | controller | }
failure
2025-09-30 00:12:41.311549 | 
2025-09-30 00:12:41.311614 | PLAY RECAP
2025-09-30 00:12:41.311665 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-30 00:12:41.311728 | 
2025-09-30 00:12:41.542567 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-30 00:12:41.543545 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 00:12:42.205404 | 
2025-09-30 00:12:42.205519 | PLAY [all]
2025-09-30 00:12:42.226453 | 
2025-09-30 00:12:42.226540 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-30 00:12:43.023984 | controller | changed: non-zero return code
2025-09-30 00:12:43.036185 | 
2025-09-30 00:12:43.037005 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-30 00:12:43.065969 | controller | skipping: Conditional result was False
2025-09-30 00:12:43.072923 | 
2025-09-30 00:12:43.073004 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-30 00:12:43.108387 | 
2025-09-30 00:12:43.108535 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-30 00:12:43.138484 | 
2025-09-30 00:12:43.138892 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-30 00:12:43.162293 | controller | skipping: Conditional result was False
2025-09-30 00:12:43.169053 | 
2025-09-30 00:12:43.169132 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-30 00:12:43.200609 | 
2025-09-30 00:12:43.200774 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-30 00:12:43.224706 | controller | skipping: Conditional result was False
2025-09-30 00:12:43.231712 | 
2025-09-30 00:12:43.231783 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-30 00:12:43.246314 | controller | skipping: Conditional result was False
2025-09-30 00:12:43.253891 | 
2025-09-30 00:12:43.253961 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-30 00:12:43.268122 | controller | skipping: Conditional result was False
2025-09-30 00:12:43.300519 | 
2025-09-30 00:12:43.300595 | PLAY RECAP
2025-09-30 00:12:43.300637 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 00:12:43.300657 | 
2025-09-30 00:12:43.421522 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 00:12:43.422416 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-30 00:12:44.041918 | 
2025-09-30 00:12:44.042039 | PLAY [all:!appliance*]
2025-09-30 00:12:44.063654 | 
2025-09-30 00:12:44.063786 | TASK [unregister the node]
2025-09-30 00:12:44.197791 | controller | skipping: Conditional result was False
2025-09-30 00:12:44.211207 | 
2025-09-30 00:12:44.211405 | TASK [include_role : fetch-output]
2025-09-30 00:12:44.250783 | controller | ok
2025-09-30 00:12:44.286797 | 
2025-09-30 00:12:44.286987 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 00:12:44.343821 | controller | skipping: Conditional result was False
2025-09-30 00:12:44.352502 | 
2025-09-30 00:12:44.352596 | TASK [fetch-output : Set log path for single node]
2025-09-30 00:12:44.395213 | controller | ok
2025-09-30 00:12:44.402717 | 
2025-09-30 00:12:44.402809 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 00:12:44.805666 | controller -> localhost | ok: "/var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/logs"
2025-09-30 00:12:45.016783 | controller -> localhost | changed: "/var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/artifacts"
2025-09-30 00:12:45.231865 | controller -> localhost | changed: "/var/lib/zuul/builds/26f7cead98fb4dcda6fafed61394c131/work/docs"
2025-09-30 00:12:45.249221 | 
2025-09-30 00:12:45.249363 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 00:12:46.578920 | controller | changed:
2025-09-30 00:12:46.579255 | controller | .d..t...... ./
2025-09-30 00:12:46.579318 | controller | cd+++++++++ controller/
2025-09-30 00:12:46.579390 | controller | changed: All items complete
2025-09-30 00:12:46.579437 | 
2025-09-30 00:12:47.630623 | controller | changed: .d..t...... ./
2025-09-30 00:12:48.578316 | controller | changed: .d..t...... ./
2025-09-30 00:12:48.596050 | 
2025-09-30 00:12:48.596157 | TASK [include_role : fetch-output-openshift]
2025-09-30 00:12:48.619954 | controller | skipping: Conditional result was False
2025-09-30 00:12:48.629987 | 
2025-09-30 00:12:48.630121 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 00:12:48.664071 | controller | skipping: Conditional result was False
2025-09-30 00:12:48.672819 | controller | skipping: Conditional result was False
2025-09-30 00:12:48.730764 | 
2025-09-30 00:12:48.730963 | PLAY [localhost]
2025-09-30 00:12:48.745507 | 
2025-09-30 00:12:48.745588 | TASK [Run Zuul manifest role]
2025-09-30 00:12:48.765335 | localhost | ok
2025-09-30 00:12:48.782256 | 
2025-09-30 00:12:48.782338 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 00:12:49.197879 | localhost | changed
2025-09-30 00:12:49.202933 | 
2025-09-30 00:12:49.202996 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 00:12:49.231327 | localhost | ok
2025-09-30 00:12:49.239282 | 
2025-09-30 00:12:49.239347 | TASK [Set zuul-log-path fact]
2025-09-30 00:12:49.259307 | localhost | ok
2025-09-30 00:12:49.281086 | 
2025-09-30 00:12:49.281193 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 00:12:49.317366 | localhost | ok
2025-09-30 00:12:49.327175 | 
2025-09-30 00:12:49.327262 | LOOP [Run upload-logs-swift role]
2025-09-30 00:12:49.361415 | localhost | Output suppressed because no_log was given
2025-09-30 00:12:49.401143 | 
2025-09-30 00:12:49.401237 | TASK [Set zuul-log-path fact]
2025-09-30 00:12:49.445721 | localhost | skipping: Conditional result was False
2025-09-30 00:12:49.451086 | 
2025-09-30 00:12:49.451155 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-30 00:12:49.881248 | localhost -> localhost | ok: Runtime: 0:00:00.008923
2025-09-30 00:12:49.893337 | 
2025-09-30 00:12:49.893483 | TASK [upload-logs-swift : Upload logs to swift]