2025-09-22 00:15:52.503491 | Job console starting...
2025-09-22 00:15:52.516712 | Updating repositories
2025-09-22 00:15:52.653345 | Preparing job workspace
2025-09-22 00:15:56.368149 | Running Ansible setup...
2025-09-22 00:16:03.028954 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-22 00:16:03.608053 | 
2025-09-22 00:16:03.608201 | PLAY [localhost]
2025-09-22 00:16:03.616803 | 
2025-09-22 00:16:03.617092 | TASK [Gathering Facts]
2025-09-22 00:16:04.669362 | localhost | ok
2025-09-22 00:16:04.687168 | 
2025-09-22 00:16:04.687324 | TASK [Setup log path fact]
2025-09-22 00:16:04.706782 | localhost | ok
2025-09-22 00:16:04.720579 | 
2025-09-22 00:16:04.720648 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-22 00:16:04.758317 | localhost | ok
2025-09-22 00:16:04.765939 | 
2025-09-22 00:16:04.766003 | TASK [emit-job-header : Print job information]
2025-09-22 00:16:04.821115 | # Job Information
2025-09-22 00:16:04.821422 | Ansible Version: 2.15.12
2025-09-22 00:16:04.821501 | Job: ansible-test-sanity-docker-devel
2025-09-22 00:16:04.821557 | Pipeline: periodic
2025-09-22 00:16:04.821610 | Executor: ze02.softwarefactory-project.io
2025-09-22 00:16:04.821655 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-22 00:16:04.821752 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/853/ansible/853414c46bb541cbb3f550edaffc5505/
2025-09-22 00:16:04.821800 | Event ID: 80fa768b351f40cb92b41db9ba32389a
2025-09-22 00:16:04.834613 | 
2025-09-22 00:16:04.834881 | LOOP [emit-job-header : Print node information]
2025-09-22 00:16:04.957978 | localhost | ok:
2025-09-22 00:16:04.958176 | localhost | # Node Information
2025-09-22 00:16:04.958214 | localhost | Inventory Hostname: controller
2025-09-22 00:16:04.958242 | localhost | Hostname: ip-172-16-232-104
2025-09-22 00:16:04.958268 | localhost | Username: zuul-worker
2025-09-22 00:16:04.958296 | localhost | Distro: Fedora 37
2025-09-22 00:16:04.958321 | localhost | Provider: ansible-us-east-2
2025-09-22 00:16:04.958345 | localhost | Region: us-east-2
2025-09-22 00:16:04.958367 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-22 00:16:04.958390 | localhost | Product Name: t3.small
2025-09-22 00:16:04.958414 | localhost | Interface IP: 3.135.18.70
2025-09-22 00:16:04.982602 | 
2025-09-22 00:16:04.982889 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-22 00:16:05.388709 | localhost -> localhost | changed
2025-09-22 00:16:05.402859 | 
2025-09-22 00:16:05.403021 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-22 00:16:06.413513 | localhost -> localhost | changed
2025-09-22 00:16:06.455752 | 
2025-09-22 00:16:06.455889 | PLAY [all:!appliance*]
2025-09-22 00:16:06.486916 | 
2025-09-22 00:16:06.487022 | TASK [include_role : start-zuul-console]
2025-09-22 00:16:06.509256 | controller | ok
2025-09-22 00:16:06.527186 | 
2025-09-22 00:16:06.527271 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-22 00:16:07.453997 | controller | ok
2025-09-22 00:16:07.477417 | 
2025-09-22 00:16:07.477555 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-22 00:16:09.427808 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-22 00:16:09.443620 | 
2025-09-22 00:16:09.443881 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-22 00:16:09.596269 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.603887 | 
2025-09-22 00:16:09.603977 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-22 00:16:09.639850 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.647057 | 
2025-09-22 00:16:09.647143 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-22 00:16:09.682536 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.689894 | 
2025-09-22 00:16:09.689994 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-22 00:16:09.735932 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.742484 | 
2025-09-22 00:16:09.742564 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-22 00:16:09.759695 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.770272 | 
2025-09-22 00:16:09.770449 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-22 00:16:09.797444 | controller | skipping: Conditional result was False
2025-09-22 00:16:09.816820 | 
2025-09-22 00:16:09.817008 | TASK [Disable Fedora Modular]
2025-09-22 00:16:10.564103 | controller | changed
2025-09-22 00:16:10.576878 | 
2025-09-22 00:16:10.577057 | TASK [Enable EPEL]
2025-09-22 00:16:10.617369 | controller | skipping: Conditional result was False
2025-09-22 00:16:10.631046 | 
2025-09-22 00:16:10.631211 | TASK [Register the RHEL node]
2025-09-22 00:16:10.812016 | 
2025-09-22 00:16:10.812374 | TASK [Show the subscription-manager status]
2025-09-22 00:16:11.038812 | controller | skipping: Conditional result was False
2025-09-22 00:16:11.046703 | 
2025-09-22 00:16:11.046779 | TASK [Enable EPEL on RHEL]
2025-09-22 00:16:11.197634 | controller | skipping: Conditional result was False
2025-09-22 00:16:11.219110 | 
2025-09-22 00:16:11.219437 | TASK [Install git and tox]
2025-09-22 00:17:45.822812 | controller | changed
2025-09-22 00:17:45.831444 | 
2025-09-22 00:17:45.831535 | TASK [include_role : prepare-workspace]
2025-09-22 00:17:45.868359 | controller | ok
2025-09-22 00:17:45.895858 | 
2025-09-22 00:17:45.895961 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-22 00:17:46.507311 | controller | ok
2025-09-22 00:17:46.530174 | 
2025-09-22 00:17:46.530272 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-22 00:17:58.844494 | controller | Output suppressed because no_log was given
2025-09-22 00:17:58.858993 | 
2025-09-22 00:17:58.859113 | TASK [include_role : prepare-workspace-openshift]
2025-09-22 00:17:58.885479 | controller | skipping: Conditional result was False
2025-09-22 00:17:58.966379 | 
2025-09-22 00:17:58.966522 | PLAY [all:!appliance]
2025-09-22 00:17:58.982378 | 
2025-09-22 00:17:58.982529 | TASK [Run add-build-sshkey role (RSA)]
2025-09-22 00:17:59.013894 | controller | ok
2025-09-22 00:17:59.029777 | 
2025-09-22 00:17:59.029864 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-22 00:17:59.332175 | controller -> localhost | ok
2025-09-22 00:17:59.346467 | 
2025-09-22 00:17:59.346606 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-22 00:17:59.385403 | controller | ok
2025-09-22 00:17:59.413415 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-22 00:17:59.422344 | 
2025-09-22 00:17:59.422435 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-22 00:17:59.967363 | controller -> localhost | Generating public/private rsa key pair.
2025-09-22 00:17:59.967602 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_rsa.
2025-09-22 00:17:59.967639 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_rsa.pub.
2025-09-22 00:17:59.967696 | controller -> localhost | The key fingerprint is:
2025-09-22 00:17:59.967731 | controller -> localhost | SHA256:DZi+63EjXnXJ5mrMTff3Nzp0tBaLqDClqMlI0w/N3xY zuul-build-sshkey
2025-09-22 00:17:59.967758 | controller -> localhost | The key's randomart image is:
2025-09-22 00:17:59.967778 | controller -> localhost | +---[RSA 2048]----+
2025-09-22 00:17:59.967796 | controller -> localhost | |                 |
2025-09-22 00:17:59.967814 | controller -> localhost | |       o         |
2025-09-22 00:17:59.967832 | controller -> localhost | |      o .        |
2025-09-22 00:17:59.967850 | controller -> localhost | |     .   + . . o |
2025-09-22 00:17:59.967867 | controller -> localhost | |  . o o S o * o +|
2025-09-22 00:17:59.967898 | controller -> localhost | | o o + = E =.o.= |
2025-09-22 00:17:59.967922 | controller -> localhost | |. + = = Boooo.o. |
2025-09-22 00:17:59.967942 | controller -> localhost | | . + o B =+... .+|
2025-09-22 00:17:59.967961 | controller -> localhost | |     .+ ...  .o *|
2025-09-22 00:17:59.967982 | controller -> localhost | +----[SHA256]-----+
2025-09-22 00:17:59.968035 | controller -> localhost | ok: Runtime: 0:00:00.083081
2025-09-22 00:17:59.976620 | 
2025-09-22 00:17:59.976708 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-22 00:18:00.007657 | controller | ok
2025-09-22 00:18:00.018049 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-22 00:18:00.027556 | 
2025-09-22 00:18:00.027641 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-22 00:18:00.053947 | controller | skipping: Conditional result was False
2025-09-22 00:18:00.060735 | 
2025-09-22 00:18:00.060807 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-22 00:18:00.853398 | controller | changed
2025-09-22 00:18:00.866596 | 
2025-09-22 00:18:00.866784 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-22 00:18:01.367487 | controller | ok
2025-09-22 00:18:01.380126 | 
2025-09-22 00:18:01.380261 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-22 00:18:04.384003 | controller | changed
2025-09-22 00:18:04.396102 | 
2025-09-22 00:18:04.396243 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-22 00:18:06.416088 | controller | changed
2025-09-22 00:18:06.425000 | 
2025-09-22 00:18:06.425099 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-22 00:18:06.461703 | controller | skipping: Conditional result was False
2025-09-22 00:18:06.470953 | 
2025-09-22 00:18:06.471055 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-22 00:18:06.915083 | controller -> localhost | changed
2025-09-22 00:18:06.930709 | 
2025-09-22 00:18:06.930810 | TASK [add-build-sshkey : Add back temp key]
2025-09-22 00:18:07.279559 | controller -> localhost | Identity added: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_rsa (zuul-build-sshkey)
2025-09-22 00:18:07.280217 | controller -> localhost | ok: Runtime: 0:00:00.009111
2025-09-22 00:18:07.297597 | 
2025-09-22 00:18:07.297801 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-22 00:18:07.841263 | controller | ok
2025-09-22 00:18:07.853155 | 
2025-09-22 00:18:07.853402 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-22 00:18:07.880125 | controller | skipping: Conditional result was False
2025-09-22 00:18:07.903352 | 
2025-09-22 00:18:07.903545 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-22 00:18:07.949581 | controller | ok
2025-09-22 00:18:07.977347 | 
2025-09-22 00:18:07.977491 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-22 00:18:08.295321 | controller -> localhost | ok
2025-09-22 00:18:08.312420 | 
2025-09-22 00:18:08.312698 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-22 00:18:08.375181 | controller | ok
2025-09-22 00:18:08.398648 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-22 00:18:08.408547 | 
2025-09-22 00:18:08.408642 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-22 00:18:08.730569 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-22 00:18:08.730923 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_ecdsa.
2025-09-22 00:18:08.730961 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_ecdsa.pub.
2025-09-22 00:18:08.731019 | controller -> localhost | The key fingerprint is:
2025-09-22 00:18:08.731043 | controller -> localhost | SHA256:WDjz0urhxkZ4hA3tNRgPShyMSGKMt3MUjjTJhvIH2OE zuul-build-sshkey
2025-09-22 00:18:08.731084 | controller -> localhost | The key's randomart image is:
2025-09-22 00:18:08.731108 | controller -> localhost | +---[ECDSA 521]---+
2025-09-22 00:18:08.731126 | controller -> localhost | |=O+*++oo         |
2025-09-22 00:18:08.731165 | controller -> localhost | |O+O==.o+o        |
2025-09-22 00:18:08.731187 | controller -> localhost | |.+E+o=+.o.       |
2025-09-22 00:18:08.731205 | controller -> localhost | |  + + +B         |
2025-09-22 00:18:08.731221 | controller -> localhost | |   + oo S        |
2025-09-22 00:18:08.731266 | controller -> localhost | |    . oo         |
2025-09-22 00:18:08.731283 | controller -> localhost | |     +o          |
2025-09-22 00:18:08.731300 | controller -> localhost | |     o+.         |
2025-09-22 00:18:08.731342 | controller -> localhost | |     oo          |
2025-09-22 00:18:08.731361 | controller -> localhost | +----[SHA256]-----+
2025-09-22 00:18:08.731437 | controller -> localhost | ok: Runtime: 0:00:00.010290
2025-09-22 00:18:08.738796 | 
2025-09-22 00:18:08.738861 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-22 00:18:08.770293 | controller | ok
2025-09-22 00:18:08.778087 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-22 00:18:08.787213 | 
2025-09-22 00:18:08.787306 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-22 00:18:08.813529 | controller | skipping: Conditional result was False
2025-09-22 00:18:08.821057 | 
2025-09-22 00:18:08.821135 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-22 00:18:09.287362 | controller | changed
2025-09-22 00:18:09.299807 | 
2025-09-22 00:18:09.299965 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-22 00:18:09.960916 | controller | ok
2025-09-22 00:18:09.969231 | 
2025-09-22 00:18:09.969326 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-22 00:18:11.313194 | controller | changed
2025-09-22 00:18:11.329150 | 
2025-09-22 00:18:11.329378 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-22 00:18:12.692055 | controller | changed
2025-09-22 00:18:12.697901 | 
2025-09-22 00:18:12.697965 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-22 00:18:12.734026 | controller | skipping: Conditional result was False
2025-09-22 00:18:12.808155 | 
2025-09-22 00:18:12.808345 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-22 00:18:13.132039 | controller -> localhost | changed
2025-09-22 00:18:13.165474 | 
2025-09-22 00:18:13.165764 | TASK [add-build-sshkey : Add back temp key]
2025-09-22 00:18:13.534510 | controller -> localhost | Identity added: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/853414c46bb541cbb3f550edaffc5505_id_ecdsa (zuul-build-sshkey)
2025-09-22 00:18:13.534971 | controller -> localhost | ok: Runtime: 0:00:00.010856
2025-09-22 00:18:13.549528 | 
2025-09-22 00:18:13.549770 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-22 00:18:13.951486 | controller | ok
2025-09-22 00:18:13.960539 | 
2025-09-22 00:18:13.960717 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-22 00:18:13.984821 | controller | skipping: Conditional result was False
2025-09-22 00:18:13.999028 | 
2025-09-22 00:18:13.999201 | TASK [include_role : remove-zuul-sshkey]
2025-09-22 00:18:14.023751 | controller | skipping: Conditional result was False
2025-09-22 00:18:14.031469 | 
2025-09-22 00:18:14.031572 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-22 00:18:14.415926 | controller | ok: "logs"
2025-09-22 00:18:14.416255 | controller | ok: All items complete
2025-09-22 00:18:14.416281 | 
2025-09-22 00:18:14.707416 | controller | ok: "artifacts"
2025-09-22 00:18:14.996085 | controller | ok: "docs"
2025-09-22 00:18:15.007574 | 
2025-09-22 00:18:15.008396 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-22 00:18:15.342523 | controller | changed: "logs"
2025-09-22 00:18:15.670372 | controller | changed: "artifacts"
2025-09-22 00:18:15.965652 | controller | changed: "docs"
2025-09-22 00:18:16.047284 | 
2025-09-22 00:18:16.047427 | PLAY RECAP
2025-09-22 00:18:16.047486 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-22 00:18:16.047521 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-22 00:18:16.047545 | 
2025-09-22 00:18:16.197629 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-22 00:18:16.198788 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-22 00:18:16.781492 | 
2025-09-22 00:18:16.781648 | PLAY [all]
2025-09-22 00:18:16.803433 | 
2025-09-22 00:18:16.803539 | TASK [Install binary dependencies]
2025-09-22 00:18:16.873649 | controller | ok
2025-09-22 00:18:16.892869 | 
2025-09-22 00:18:16.892964 | TASK [bindep : Include find tasks]
2025-09-22 00:18:16.933190 | controller | ok
2025-09-22 00:18:16.941478 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-22 00:18:16.947889 | 
2025-09-22 00:18:16.947958 | TASK [bindep : Look for bindep.txt]
2025-09-22 00:18:17.557828 | controller | ok
2025-09-22 00:18:17.565355 | 
2025-09-22 00:18:17.565453 | TASK [bindep : Define bindep_file fact]
2025-09-22 00:18:17.592582 | controller | skipping: Conditional result was False
2025-09-22 00:18:17.600556 | 
2025-09-22 00:18:17.600754 | TASK [bindep : Look for other-requirements.txt]
2025-09-22 00:18:17.934373 | controller | ok
2025-09-22 00:18:17.948647 | 
2025-09-22 00:18:17.948878 | TASK [bindep : Define bindep_file fact]
2025-09-22 00:18:17.976587 | controller | skipping: Conditional result was False
2025-09-22 00:18:17.986967 | 
2025-09-22 00:18:17.987275 | TASK [bindep : Look for bindep fallback file]
2025-09-22 00:18:18.015806 | controller | skipping: Conditional result was False
2025-09-22 00:18:18.026649 | 
2025-09-22 00:18:18.026860 | TASK [bindep : Define bindep_file fact]
2025-09-22 00:18:18.053550 | controller | skipping: Conditional result was False
2025-09-22 00:18:18.065884 | 
2025-09-22 00:18:18.066091 | TASK [bindep : Include bindep tasks]
2025-09-22 00:18:18.103349 | controller | skipping: Conditional result was False
2025-09-22 00:18:18.113609 | 
2025-09-22 00:18:18.113802 | TASK [bindep : Include install tasks]
2025-09-22 00:18:18.150481 | controller | skipping: Conditional result was False
2025-09-22 00:18:18.160651 | 
2025-09-22 00:18:18.160835 | LOOP [bindep : Include package tasks]
2025-09-22 00:18:18.229553 | 
2025-09-22 00:18:18.229768 | TASK [Run test-setup role]
2025-09-22 00:18:18.260405 | controller | ok
2025-09-22 00:18:18.279222 | 
2025-09-22 00:18:18.279349 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-22 00:18:18.617826 | controller | ok
2025-09-22 00:18:18.633958 | 
2025-09-22 00:18:18.634188 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-22 00:18:18.785095 | controller | skipping: Conditional result was False
2025-09-22 00:18:18.824599 | 
2025-09-22 00:18:18.824777 | PLAY RECAP
2025-09-22 00:18:18.824827 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-22 00:18:18.824847 | 
2025-09-22 00:18:18.965311 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-22 00:18:18.966320 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-22 00:18:19.679066 | 
2025-09-22 00:18:19.679277 | PLAY [controller]
2025-09-22 00:18:19.712702 | 
2025-09-22 00:18:19.712916 | TASK [Create the /root directory]
2025-09-22 00:18:20.454897 | controller | ok
2025-09-22 00:18:20.462970 | 
2025-09-22 00:18:20.463098 | TASK [Install glibc-langpack-en]
2025-09-22 00:18:28.678222 | controller | ok: Nothing to do
2025-09-22 00:18:28.683860 | 
2025-09-22 00:18:28.683959 | TASK [Ensure controller directory exists]
2025-09-22 00:18:29.117658 | controller | changed
2025-09-22 00:18:29.130246 | 
2025-09-22 00:18:29.130451 | TASK [Install container runtime]
2025-09-22 00:18:29.185644 | controller | ok
2025-09-22 00:18:29.234855 | 
2025-09-22 00:18:29.235038 | LOOP [ensure-podman : Find distribution installation]
2025-09-22 00:18:29.282633 | controller | ok: "/var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-22 00:18:29.300316 | controller | included: /var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-22 00:18:29.312432 | 
2025-09-22 00:18:29.312570 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-22 00:19:48.530826 | controller | changed
2025-09-22 00:19:48.544253 | 
2025-09-22 00:19:48.544393 | TASK [ensure-podman : Fetch podman version]
2025-09-22 00:19:49.267359 | controller | Client:       Podman Engine
2025-09-22 00:19:49.292617 | controller | Version:      4.6.2
2025-09-22 00:19:49.292668 | controller | API Version:  4.6.2
2025-09-22 00:19:49.292677 | controller | Go Version:   go1.19.12
2025-09-22 00:19:49.292699 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-22 00:19:49.292709 | controller | OS/Arch:      linux/amd64
2025-09-22 00:19:49.696041 | controller | ok: Runtime: 0:00:00.217950
2025-09-22 00:19:49.709909 | 
2025-09-22 00:19:49.710114 | TASK [ensure-podman : Print podman version installed]
2025-09-22 00:19:49.759770 | Podman version: Client:       Podman Engine
2025-09-22 00:19:49.760043 | Version:      4.6.2
2025-09-22 00:19:49.760108 | API Version:  4.6.2
2025-09-22 00:19:49.760155 | Go Version:   go1.19.12
2025-09-22 00:19:49.760198 | Built:        Mon Aug 28 19:38:31 2023
2025-09-22 00:19:49.760244 | OS/Arch:      linux/amd64
2025-09-22 00:19:49.772713 | 
2025-09-22 00:19:49.772855 | TASK [ensure-podman : Validate podman engine]
2025-09-22 00:19:49.919080 | controller | skipping: Conditional result was False
2025-09-22 00:19:49.927180 | 
2025-09-22 00:19:49.927269 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-22 00:19:49.954215 | controller | skipping: Conditional result was False
2025-09-22 00:19:49.968723 | 
2025-09-22 00:19:49.968817 | TASK [Ensure python3.8 is present]
2025-09-22 00:19:49.994009 | controller | skipping: Conditional result was False
2025-09-22 00:19:50.002212 | 
2025-09-22 00:19:50.002296 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-22 00:19:50.025111 | controller | ok
2025-09-22 00:19:50.049187 | 
2025-09-22 00:19:50.049296 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-22 00:19:53.675886 | controller | ok: Nothing to do
2025-09-22 00:19:53.687517 | 
2025-09-22 00:19:53.687723 | TASK [our-ensure-python : Also install python3-devel]
2025-09-22 00:20:09.833612 | controller | changed
2025-09-22 00:20:09.857774 | 
2025-09-22 00:20:09.857950 | TASK [Run ensure-virtualenv role]
2025-09-22 00:20:09.883309 | controller | ok
2025-09-22 00:20:09.911064 | 
2025-09-22 00:20:09.911177 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-22 00:20:10.344200 | controller | /usr/bin/virtualenv
2025-09-22 00:20:10.549179 | controller | ok: Runtime: 0:00:00.004698
2025-09-22 00:20:10.562599 | 
2025-09-22 00:20:10.562770 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-22 00:20:10.599423 | controller | skipping: Conditional result was False
2025-09-22 00:20:10.599942 | controller | ok: All items complete
2025-09-22 00:20:10.600007 | 
2025-09-22 00:20:10.665760 | 
2025-09-22 00:20:10.665939 | TASK [Find the full path of the Python interpreter]
2025-09-22 00:20:11.119287 | controller | /usr/bin/python3
2025-09-22 00:20:11.303593 | controller | ok
2025-09-22 00:20:11.315742 | 
2025-09-22 00:20:11.315885 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-22 00:20:12.794965 | controller | created virtual environment CPython3.11.0.final.0-64 in 744ms
2025-09-22 00:20:12.852310 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-22 00:20:12.853012 | 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-22 00:20:12.853129 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-22 00:20:12.853155 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-22 00:20:12.978251 | controller | changed
2025-09-22 00:20:12.991582 | 
2025-09-22 00:20:12.991773 | TASK [Set selinux package]
2025-09-22 00:20:13.030145 | controller | ok
2025-09-22 00:20:13.040904 | 
2025-09-22 00:20:13.041044 | TASK [Set selinux package (Fedora)]
2025-09-22 00:20:13.092027 | controller | ok
2025-09-22 00:20:13.103724 | 
2025-09-22 00:20:13.103874 | TASK [Install selinux into virtualenv]
2025-09-22 00:20:15.776360 | controller | Collecting selinux-please-lie-to-me
2025-09-22 00:20:15.868617 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-22 00:20:16.399561 | controller | Collecting setuptools<50.0.0
2025-09-22 00:20:16.414600 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-22 00:20:16.548274 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.5 MB/s eta 0:00:00
2025-09-22 00:20:16.702450 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-22 00:20:16.702744 | controller |   Attempting uninstall: setuptools
2025-09-22 00:20:16.707794 | controller |     Found existing installation: setuptools 62.6.0
2025-09-22 00:20:16.818178 | controller |     Uninstalling setuptools-62.6.0:
2025-09-22 00:20:16.833387 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-22 00:20:17.591577 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-22 00:20:17.801466 | controller |
2025-09-22 00:20:18.016811 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-22 00:20:18.016855 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-22 00:20:18.277282 | controller | ok: Runtime: 0:00:04.428904
2025-09-22 00:20:18.289650 | 
2025-09-22 00:20:18.289814 | TASK [Install pytest-forked into virtualenv]
2025-09-22 00:20:19.517884 | controller | Collecting pytest-forked
2025-09-22 00:20:19.606817 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-22 00:20:19.666979 | controller | Collecting py
2025-09-22 00:20:19.680718 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-22 00:20:19.715671 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-09-22 00:20:19.887897 | controller | Collecting pytest>=3.10
2025-09-22 00:20:19.901176 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-22 00:20:19.952733 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.5 MB/s eta 0:00:00
2025-09-22 00:20:20.009859 | controller | Collecting iniconfig>=1
2025-09-22 00:20:20.023853 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-22 00:20:20.091859 | controller | Collecting packaging>=20
2025-09-22 00:20:20.105130 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-22 00:20:20.115406 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.7 MB/s eta 0:00:00
2025-09-22 00:20:20.162546 | controller | Collecting pluggy<2,>=1.5
2025-09-22 00:20:20.175499 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-22 00:20:20.250751 | controller | Collecting pygments>=2.7.2
2025-09-22 00:20:20.264005 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-22 00:20:20.360443 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.1 MB/s eta 0:00:00
2025-09-22 00:20:20.493264 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-22 00:20:22.703315 | 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-22 00:20:22.721117 | controller |
2025-09-22 00:20:22.910327 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-22 00:20:22.910372 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-22 00:20:22.978523 | controller | ok: Runtime: 0:00:04.130353
2025-09-22 00:20:22.991444 | 
2025-09-22 00:20:22.991629 | TASK [Update pip]
2025-09-22 00:20:24.211156 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-22 00:20:24.506624 | controller | Collecting pip
2025-09-22 00:20:24.598028 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-22 00:20:24.754553 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.6 MB/s eta 0:00:00
2025-09-22 00:20:24.925819 | controller | Installing collected packages: pip
2025-09-22 00:20:24.926137 | controller |   Attempting uninstall: pip
2025-09-22 00:20:24.934194 | controller |     Found existing installation: pip 22.2.2
2025-09-22 00:20:25.241698 | controller |     Uninstalling pip-22.2.2:
2025-09-22 00:20:25.271313 | controller |       Successfully uninstalled pip-22.2.2
2025-09-22 00:20:27.065969 | controller | Successfully installed pip-25.2
2025-09-22 00:20:27.653501 | controller | ok: Runtime: 0:00:03.740618
2025-09-22 00:20:27.667556 | 
2025-09-22 00:20:27.667779 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-22 00:20:28.189738 | controller | changed
2025-09-22 00:20:28.201875 | 
2025-09-22 00:20:28.202014 | TASK [Install ansible into virtualenv]
2025-09-22 00:20:29.289463 | controller | Processing ./src/github.com/ansible/ansible
2025-09-22 00:20:29.296115 | controller |   Installing build dependencies: started
2025-09-22 00:20:31.147301 | controller |   Installing build dependencies: finished with status 'done'
2025-09-22 00:20:31.148338 | controller |   Getting requirements to build wheel: started
2025-09-22 00:20:32.676297 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-22 00:20:32.677880 | controller |   Preparing metadata (pyproject.toml): started
2025-09-22 00:20:33.607305 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-22 00:20:33.610987 | 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-22 00:20:33.615890 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-22 00:20:33.874316 | controller | ERROR
2025-09-22 00:20:33.874788 | controller | {
2025-09-22 00:20:33.874880 | controller |   "delta": "0:00:05.113839",
2025-09-22 00:20:33.874943 | controller |   "end": "2025-09-22 00:20:33.771791",
2025-09-22 00:20:33.874998 | controller |   "msg": "non-zero return code",
2025-09-22 00:20:33.875066 | controller |   "rc": 1,
2025-09-22 00:20:33.875103 | controller |   "start": "2025-09-22 00:20:28.657952"
2025-09-22 00:20:33.875137 | controller | }
failure
2025-09-22 00:20:33.881229 | 
2025-09-22 00:20:33.881346 | PLAY RECAP
2025-09-22 00:20:33.881440 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-22 00:20:33.881483 | 
2025-09-22 00:20:34.065331 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-22 00:20:34.066865 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-22 00:20:34.712172 | 
2025-09-22 00:20:34.712290 | PLAY [all]
2025-09-22 00:20:34.732442 | 
2025-09-22 00:20:34.732520 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-22 00:20:35.526729 | controller | changed: non-zero return code
2025-09-22 00:20:35.539247 | 
2025-09-22 00:20:35.539490 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-22 00:20:35.568925 | controller | skipping: Conditional result was False
2025-09-22 00:20:35.582778 | 
2025-09-22 00:20:35.582950 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-22 00:20:35.626984 | 
2025-09-22 00:20:35.627445 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-22 00:20:35.665033 | 
2025-09-22 00:20:35.665235 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-22 00:20:35.692882 | controller | skipping: Conditional result was False
2025-09-22 00:20:35.702858 | 
2025-09-22 00:20:35.702971 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-22 00:20:35.741036 | 
2025-09-22 00:20:35.741324 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-22 00:20:35.769149 | controller | skipping: Conditional result was False
2025-09-22 00:20:35.776903 | 
2025-09-22 00:20:35.777001 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-22 00:20:35.801509 | controller | skipping: Conditional result was False
2025-09-22 00:20:35.812255 | 
2025-09-22 00:20:35.812390 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-22 00:20:35.839412 | controller | skipping: Conditional result was False
2025-09-22 00:20:35.879415 | 
2025-09-22 00:20:35.879543 | PLAY RECAP
2025-09-22 00:20:35.879607 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-22 00:20:35.879635 | 
2025-09-22 00:20:36.070884 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-22 00:20:36.072740 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-22 00:20:36.676681 | 
2025-09-22 00:20:36.676835 | PLAY [all:!appliance*]
2025-09-22 00:20:36.699148 | 
2025-09-22 00:20:36.699346 | TASK [unregister the node]
2025-09-22 00:20:36.842149 | controller | skipping: Conditional result was False
2025-09-22 00:20:36.855781 | 
2025-09-22 00:20:36.855952 | TASK [include_role : fetch-output]
2025-09-22 00:20:36.916743 | controller | ok
2025-09-22 00:20:36.956866 | 
2025-09-22 00:20:36.957044 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-22 00:20:37.034741 | controller | skipping: Conditional result was False
2025-09-22 00:20:37.048592 | 
2025-09-22 00:20:37.048783 | TASK [fetch-output : Set log path for single node]
2025-09-22 00:20:37.110322 | controller | ok
2025-09-22 00:20:37.122519 | 
2025-09-22 00:20:37.122699 | LOOP [fetch-output : Ensure local output dirs]
2025-09-22 00:20:37.630834 | controller -> localhost | ok: "/var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/logs"
2025-09-22 00:20:37.926404 | controller -> localhost | changed: "/var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/artifacts"
2025-09-22 00:20:38.229491 | controller -> localhost | changed: "/var/lib/zuul/builds/853414c46bb541cbb3f550edaffc5505/work/docs"
2025-09-22 00:20:38.247613 | 
2025-09-22 00:20:38.247876 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-22 00:20:39.483003 | controller | changed:
2025-09-22 00:20:39.483816 | controller | .d..t...... ./
2025-09-22 00:20:39.483949 | controller | cd+++++++++ controller/
2025-09-22 00:20:39.484072 | controller | changed: All items complete
2025-09-22 00:20:39.484148 | 
2025-09-22 00:20:40.522609 | controller | changed: .d..t...... ./
2025-09-22 00:20:41.652538 | controller | changed: .d..t...... ./
2025-09-22 00:20:41.672803 | 
2025-09-22 00:20:41.672989 | TASK [include_role : fetch-output-openshift]
2025-09-22 00:20:41.699324 | controller | skipping: Conditional result was False
2025-09-22 00:20:41.708337 | 
2025-09-22 00:20:41.708432 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-22 00:20:41.754648 | controller | skipping: Conditional result was False
2025-09-22 00:20:41.764795 | controller | skipping: Conditional result was False
2025-09-22 00:20:41.817555 | 
2025-09-22 00:20:41.817722 | PLAY [localhost]
2025-09-22 00:20:41.837618 | 
2025-09-22 00:20:41.837763 | TASK [Run Zuul manifest role]
2025-09-22 00:20:41.858493 | localhost | ok
2025-09-22 00:20:41.878693 | 
2025-09-22 00:20:41.878786 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-22 00:20:42.312847 | localhost | changed
2025-09-22 00:20:42.323980 | 
2025-09-22 00:20:42.324145 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-22 00:20:42.383491 | localhost | ok
2025-09-22 00:20:42.402063 | 
2025-09-22 00:20:42.402236 | TASK [Set zuul-log-path fact]
2025-09-22 00:20:42.439980 | localhost | ok
2025-09-22 00:20:42.468558 | 
2025-09-22 00:20:42.468721 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-22 00:20:42.515212 | localhost | ok
2025-09-22 00:20:42.536022 | 
2025-09-22 00:20:42.536406 | LOOP [Run upload-logs-swift role]
2025-09-22 00:20:42.587044 | localhost | Output suppressed because no_log was given
2025-09-22 00:20:42.640129 | 
2025-09-22 00:20:42.640316 | TASK [Set zuul-log-path fact]
2025-09-22 00:20:42.677198 | localhost | skipping: Conditional result was False
2025-09-22 00:20:42.686130 | 
2025-09-22 00:20:42.686228 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-22 00:20:43.151976 | localhost -> localhost | ok: Runtime: 0:00:00.006752
2025-09-22 00:20:43.163996 | 
2025-09-22 00:20:43.164143 | TASK [upload-logs-swift : Upload logs to swift]