2025-10-02 00:11:52.835947 | Job console starting...
2025-10-02 00:11:52.848222 | Updating repositories
2025-10-02 00:11:53.005621 | Preparing job workspace
2025-10-02 00:11:56.842292 | Running Ansible setup...
2025-10-02 00:12:03.260545 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-02 00:12:03.820476 | 
2025-10-02 00:12:03.820586 | PLAY [localhost]
2025-10-02 00:12:03.828867 | 
2025-10-02 00:12:03.828941 | TASK [Gathering Facts]
2025-10-02 00:12:04.796952 | localhost | ok
2025-10-02 00:12:04.810906 | 
2025-10-02 00:12:04.810980 | TASK [Setup log path fact]
2025-10-02 00:12:04.837197 | localhost | ok
2025-10-02 00:12:04.850185 | 
2025-10-02 00:12:04.850251 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 00:12:04.887266 | localhost | ok
2025-10-02 00:12:04.894719 | 
2025-10-02 00:12:04.894786 | TASK [emit-job-header : Print job information]
2025-10-02 00:12:04.942607 | # Job Information
2025-10-02 00:12:04.942735 | Ansible Version: 2.15.12
2025-10-02 00:12:04.942767 | Job: ansible-test-sanity-docker-milestone
2025-10-02 00:12:04.942788 | Pipeline: periodic
2025-10-02 00:12:04.942806 | Executor: ze02.softwarefactory-project.io
2025-10-02 00:12:04.942824 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-02 00:12:04.942844 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/f50/ansible/f50de31893f14eff8f19187998d0c538/
2025-10-02 00:12:04.942862 | Event ID: dc6de0c9c3c649899b29042e956f2ac8
2025-10-02 00:12:04.946800 | 
2025-10-02 00:12:04.946866 | LOOP [emit-job-header : Print node information]
2025-10-02 00:12:05.072423 | localhost | ok:
2025-10-02 00:12:05.072640 | localhost | # Node Information
2025-10-02 00:12:05.072686 | localhost | Inventory Hostname: controller
2025-10-02 00:12:05.072711 | localhost | Hostname: ip-172-16-188-128
2025-10-02 00:12:05.072731 | localhost | Username: zuul-worker
2025-10-02 00:12:05.072751 | localhost | Distro: Fedora 37
2025-10-02 00:12:05.072769 | localhost | Provider: ansible-us-east-2
2025-10-02 00:12:05.072786 | localhost | Region: us-east-2
2025-10-02 00:12:05.072803 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-02 00:12:05.072820 | localhost | Product Name: t3.small
2025-10-02 00:12:05.072836 | localhost | Interface IP: 18.116.100.194
2025-10-02 00:12:05.082472 | 
2025-10-02 00:12:05.082582 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-02 00:12:05.453384 | localhost -> localhost | changed
2025-10-02 00:12:05.461704 | 
2025-10-02 00:12:05.461794 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-02 00:12:06.267919 | localhost -> localhost | changed
2025-10-02 00:12:06.287433 | 
2025-10-02 00:12:06.287490 | PLAY [all:!appliance*]
2025-10-02 00:12:06.302604 | 
2025-10-02 00:12:06.302689 | TASK [include_role : start-zuul-console]
2025-10-02 00:12:06.320831 | controller | ok
2025-10-02 00:12:06.334849 | 
2025-10-02 00:12:06.334911 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-02 00:12:07.014623 | controller | ok
2025-10-02 00:12:07.043093 | 
2025-10-02 00:12:07.043253 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-02 00:12:08.999121 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-02 00:12:09.011992 | 
2025-10-02 00:12:09.012124 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-02 00:12:09.155862 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.164195 | 
2025-10-02 00:12:09.164285 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-02 00:12:09.199614 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.207927 | 
2025-10-02 00:12:09.208012 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-02 00:12:09.234037 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.242364 | 
2025-10-02 00:12:09.242459 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-02 00:12:09.267548 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.275998 | 
2025-10-02 00:12:09.276098 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-02 00:12:09.301196 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.309353 | 
2025-10-02 00:12:09.309441 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-02 00:12:09.334598 | controller | skipping: Conditional result was False
2025-10-02 00:12:09.361530 | 
2025-10-02 00:12:09.361631 | TASK [Disable Fedora Modular]
2025-10-02 00:12:10.083418 | controller | changed
2025-10-02 00:12:10.090852 | 
2025-10-02 00:12:10.090958 | TASK [Enable EPEL]
2025-10-02 00:12:10.117803 | controller | skipping: Conditional result was False
2025-10-02 00:12:10.126283 | 
2025-10-02 00:12:10.126370 | TASK [Register the RHEL node]
2025-10-02 00:12:10.283134 | 
2025-10-02 00:12:10.283333 | TASK [Show the subscription-manager status]
2025-10-02 00:12:10.462378 | controller | skipping: Conditional result was False
2025-10-02 00:12:10.470060 | 
2025-10-02 00:12:10.470126 | TASK [Enable EPEL on RHEL]
2025-10-02 00:12:10.600489 | controller | skipping: Conditional result was False
2025-10-02 00:12:10.613497 | 
2025-10-02 00:12:10.613641 | TASK [Install git and tox]
2025-10-02 00:13:42.086323 | controller | changed
2025-10-02 00:13:42.099656 | 
2025-10-02 00:13:42.099873 | TASK [include_role : prepare-workspace]
2025-10-02 00:13:42.138352 | controller | ok
2025-10-02 00:13:42.175076 | 
2025-10-02 00:13:42.175209 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-02 00:13:42.741093 | controller | ok
2025-10-02 00:13:42.754834 | 
2025-10-02 00:13:42.754971 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-02 00:13:55.106436 | controller | Output suppressed because no_log was given
2025-10-02 00:13:55.119618 | 
2025-10-02 00:13:55.119718 | TASK [include_role : prepare-workspace-openshift]
2025-10-02 00:13:55.144976 | controller | skipping: Conditional result was False
2025-10-02 00:13:55.172067 | 
2025-10-02 00:13:55.172140 | PLAY [all:!appliance]
2025-10-02 00:13:55.190642 | 
2025-10-02 00:13:55.190727 | TASK [Run add-build-sshkey role (RSA)]
2025-10-02 00:13:55.251008 | controller | ok
2025-10-02 00:13:55.264375 | 
2025-10-02 00:13:55.264449 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-02 00:13:55.532419 | controller -> localhost | ok
2025-10-02 00:13:55.545048 | 
2025-10-02 00:13:55.545181 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-02 00:13:55.584838 | controller | ok
2025-10-02 00:13:55.610141 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-02 00:13:55.618763 | 
2025-10-02 00:13:55.618863 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-02 00:13:56.112333 | controller -> localhost | Generating public/private rsa key pair.
2025-10-02 00:13:56.112747 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_rsa.
2025-10-02 00:13:56.112820 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_rsa.pub.
2025-10-02 00:13:56.112872 | controller -> localhost | The key fingerprint is:
2025-10-02 00:13:56.112917 | controller -> localhost | SHA256:Nd/nK403hxoAQDsLCW+4ld2ykIsKwGtr4S4Ue5AC2pk zuul-build-sshkey
2025-10-02 00:13:56.112960 | controller -> localhost | The key's randomart image is:
2025-10-02 00:13:56.113002 | controller -> localhost | +---[RSA 2048]----+
2025-10-02 00:13:56.113042 | controller -> localhost | |  .  .o          |
2025-10-02 00:13:56.113085 | controller -> localhost | |o  + = +         |
2025-10-02 00:13:56.113126 | controller -> localhost | |+oooX = o o      |
2025-10-02 00:13:56.113166 | controller -> localhost | |++E= + = o o .   |
2025-10-02 00:13:56.113205 | controller -> localhost | |o+* . o S . . . .|
2025-10-02 00:13:56.113261 | controller -> localhost | |++o.       .   o |
2025-10-02 00:13:56.113310 | controller -> localhost | |o+.         . o..|
2025-10-02 00:13:56.113357 | controller -> localhost | |+            +.+o|
2025-10-02 00:13:56.113398 | controller -> localhost | |..          ..o.o|
2025-10-02 00:13:56.113446 | controller -> localhost | +----[SHA256]-----+
2025-10-02 00:13:56.113549 | controller -> localhost | ok: Runtime: 0:00:00.037403
2025-10-02 00:13:56.126833 | 
2025-10-02 00:13:56.126965 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-02 00:13:56.164298 | controller | ok
2025-10-02 00:13:56.184411 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-02 00:13:56.198381 | 
2025-10-02 00:13:56.198463 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-02 00:13:56.223528 | controller | skipping: Conditional result was False
2025-10-02 00:13:56.233005 | 
2025-10-02 00:13:56.233087 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-02 00:13:56.836421 | controller | changed
2025-10-02 00:13:56.843935 | 
2025-10-02 00:13:56.844020 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-02 00:13:57.188167 | controller | ok
2025-10-02 00:13:57.207867 | 
2025-10-02 00:13:57.208016 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-02 00:13:58.503896 | controller | changed
2025-10-02 00:13:58.517296 | 
2025-10-02 00:13:58.517462 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-02 00:13:59.838608 | controller | changed
2025-10-02 00:13:59.851432 | 
2025-10-02 00:13:59.851571 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-02 00:13:59.878804 | controller | skipping: Conditional result was False
2025-10-02 00:13:59.892556 | 
2025-10-02 00:13:59.892764 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-02 00:14:00.305741 | controller -> localhost | changed
2025-10-02 00:14:00.316579 | 
2025-10-02 00:14:00.316647 | TASK [add-build-sshkey : Add back temp key]
2025-10-02 00:14:00.645953 | controller -> localhost | Identity added: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_rsa (zuul-build-sshkey)
2025-10-02 00:14:00.646172 | controller -> localhost | ok: Runtime: 0:00:00.009785
2025-10-02 00:14:00.652248 | 
2025-10-02 00:14:00.652313 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-02 00:14:01.179530 | controller | ok
2025-10-02 00:14:01.190712 | 
2025-10-02 00:14:01.190845 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-02 00:14:01.229076 | controller | skipping: Conditional result was False
2025-10-02 00:14:01.252115 | 
2025-10-02 00:14:01.252247 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-02 00:14:01.289991 | controller | ok
2025-10-02 00:14:01.320338 | 
2025-10-02 00:14:01.320438 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-02 00:14:01.600862 | controller -> localhost | ok
2025-10-02 00:14:01.607128 | 
2025-10-02 00:14:01.607191 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-02 00:14:01.636738 | controller | ok
2025-10-02 00:14:01.647488 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-02 00:14:01.652930 | 
2025-10-02 00:14:01.652991 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-02 00:14:01.993041 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-02 00:14:01.993236 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_ecdsa.
2025-10-02 00:14:01.993265 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_ecdsa.pub.
2025-10-02 00:14:01.993296 | controller -> localhost | The key fingerprint is:
2025-10-02 00:14:01.993316 | controller -> localhost | SHA256:GoQJ1Oc3oJL7Lw+f76PK0pD/JHol7tt+XtbyaS+c2cM zuul-build-sshkey
2025-10-02 00:14:01.993336 | controller -> localhost | The key's randomart image is:
2025-10-02 00:14:01.993355 | controller -> localhost | +---[ECDSA 521]---+
2025-10-02 00:14:01.993372 | controller -> localhost | | .o.             |
2025-10-02 00:14:01.993389 | controller -> localhost | |   ..oo          |
2025-10-02 00:14:01.993406 | controller -> localhost | |   .o+..         |
2025-10-02 00:14:01.993422 | controller -> localhost | |  o ... o        |
2025-10-02 00:14:01.993439 | controller -> localhost | |   +  ..S.       |
2025-10-02 00:14:01.993456 | controller -> localhost | |  + . .o   .     |
2025-10-02 00:14:01.993472 | controller -> localhost | |   *ooo   +..=   |
2025-10-02 00:14:01.993489 | controller -> localhost | |  .oB* .oo o*.E  |
2025-10-02 00:14:01.993505 | controller -> localhost | |  .+=OX*+. .oo.. |
2025-10-02 00:14:01.993521 | controller -> localhost | +----[SHA256]-----+
2025-10-02 00:14:01.993571 | controller -> localhost | ok: Runtime: 0:00:00.016064
2025-10-02 00:14:02.000411 | 
2025-10-02 00:14:02.000480 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-02 00:14:02.031629 | controller | ok
2025-10-02 00:14:02.039182 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-02 00:14:02.050178 | 
2025-10-02 00:14:02.050252 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-02 00:14:02.065461 | controller | skipping: Conditional result was False
2025-10-02 00:14:02.075161 | 
2025-10-02 00:14:02.075322 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-02 00:14:02.622163 | controller | changed
2025-10-02 00:14:02.634851 | 
2025-10-02 00:14:02.635010 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-02 00:14:02.992529 | controller | ok
2025-10-02 00:14:03.005194 | 
2025-10-02 00:14:03.005335 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-02 00:14:04.329825 | controller | changed
2025-10-02 00:14:04.344095 | 
2025-10-02 00:14:04.344287 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-02 00:14:05.651457 | controller | changed
2025-10-02 00:14:05.664138 | 
2025-10-02 00:14:05.664270 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-02 00:14:05.691727 | controller | skipping: Conditional result was False
2025-10-02 00:14:05.705230 | 
2025-10-02 00:14:05.705366 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-02 00:14:05.986938 | controller -> localhost | changed
2025-10-02 00:14:05.997733 | 
2025-10-02 00:14:05.997800 | TASK [add-build-sshkey : Add back temp key]
2025-10-02 00:14:06.333790 | controller -> localhost | Identity added: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/f50de31893f14eff8f19187998d0c538_id_ecdsa (zuul-build-sshkey)
2025-10-02 00:14:06.334114 | controller -> localhost | ok: Runtime: 0:00:00.008537
2025-10-02 00:14:06.347056 | 
2025-10-02 00:14:06.347192 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-02 00:14:06.690924 | controller | ok
2025-10-02 00:14:06.701971 | 
2025-10-02 00:14:06.702116 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-02 00:14:06.738910 | controller | skipping: Conditional result was False
2025-10-02 00:14:06.764269 | 
2025-10-02 00:14:06.764430 | TASK [include_role : remove-zuul-sshkey]
2025-10-02 00:14:06.791057 | controller | skipping: Conditional result was False
2025-10-02 00:14:06.804104 | 
2025-10-02 00:14:06.804255 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 00:14:07.212870 | controller | ok: "logs"
2025-10-02 00:14:07.213164 | controller | ok: All items complete
2025-10-02 00:14:07.213223 | 
2025-10-02 00:14:07.454409 | controller | ok: "artifacts"
2025-10-02 00:14:07.737660 | controller | ok: "docs"
2025-10-02 00:14:07.756130 | 
2025-10-02 00:14:07.756351 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 00:14:08.099376 | controller | changed: "logs"
2025-10-02 00:14:08.395562 | controller | changed: "artifacts"
2025-10-02 00:14:08.686626 | controller | changed: "docs"
2025-10-02 00:14:08.739383 | 
2025-10-02 00:14:08.739534 | PLAY RECAP
2025-10-02 00:14:08.739597 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-02 00:14:08.739632 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 00:14:08.739657 | 
2025-10-02 00:14:08.849617 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-02 00:14:08.850489 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 00:14:09.419073 | 
2025-10-02 00:14:09.419179 | PLAY [all]
2025-10-02 00:14:09.442134 | 
2025-10-02 00:14:09.442225 | TASK [Install binary dependencies]
2025-10-02 00:14:09.513830 | controller | ok
2025-10-02 00:14:09.539849 | 
2025-10-02 00:14:09.539960 | TASK [bindep : Include find tasks]
2025-10-02 00:14:09.572060 | controller | ok
2025-10-02 00:14:09.582301 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-02 00:14:09.590721 | 
2025-10-02 00:14:09.590810 | TASK [bindep : Look for bindep.txt]
2025-10-02 00:14:10.095270 | controller | ok
2025-10-02 00:14:10.109712 | 
2025-10-02 00:14:10.109942 | TASK [bindep : Define bindep_file fact]
2025-10-02 00:14:10.138270 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.151343 | 
2025-10-02 00:14:10.151505 | TASK [bindep : Look for other-requirements.txt]
2025-10-02 00:14:10.578962 | controller | ok
2025-10-02 00:14:10.590323 | 
2025-10-02 00:14:10.590522 | TASK [bindep : Define bindep_file fact]
2025-10-02 00:14:10.628561 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.641217 | 
2025-10-02 00:14:10.641419 | TASK [bindep : Look for bindep fallback file]
2025-10-02 00:14:10.679581 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.692287 | 
2025-10-02 00:14:10.692435 | TASK [bindep : Define bindep_file fact]
2025-10-02 00:14:10.730162 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.743787 | 
2025-10-02 00:14:10.744077 | TASK [bindep : Include bindep tasks]
2025-10-02 00:14:10.781252 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.796120 | 
2025-10-02 00:14:10.796257 | TASK [bindep : Include install tasks]
2025-10-02 00:14:10.832705 | controller | skipping: Conditional result was False
2025-10-02 00:14:10.845113 | 
2025-10-02 00:14:10.845255 | LOOP [bindep : Include package tasks]
2025-10-02 00:14:10.924485 | 
2025-10-02 00:14:10.924777 | TASK [Run test-setup role]
2025-10-02 00:14:10.952472 | controller | ok
2025-10-02 00:14:10.983169 | 
2025-10-02 00:14:10.983266 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-02 00:14:11.308961 | controller | ok
2025-10-02 00:14:11.316827 | 
2025-10-02 00:14:11.316915 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-02 00:14:11.469503 | controller | skipping: Conditional result was False
2025-10-02 00:14:11.507300 | 
2025-10-02 00:14:11.507423 | PLAY RECAP
2025-10-02 00:14:11.507478 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-02 00:14:11.507506 | 
2025-10-02 00:14:11.610894 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 00:14:11.611751 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-02 00:14:12.182545 | 
2025-10-02 00:14:12.182690 | PLAY [controller]
2025-10-02 00:14:12.203713 | 
2025-10-02 00:14:12.203888 | TASK [Create the /root directory]
2025-10-02 00:14:12.985221 | controller | ok
2025-10-02 00:14:12.999362 | 
2025-10-02 00:14:12.999550 | TASK [Install glibc-langpack-en]
2025-10-02 00:14:21.192983 | controller | ok: Nothing to do
2025-10-02 00:14:21.209116 | 
2025-10-02 00:14:21.209232 | TASK [Ensure controller directory exists]
2025-10-02 00:14:21.650975 | controller | changed
2025-10-02 00:14:21.677471 | 
2025-10-02 00:14:21.677790 | TASK [Install container runtime]
2025-10-02 00:14:21.753543 | controller | ok
2025-10-02 00:14:21.803193 | 
2025-10-02 00:14:21.803438 | LOOP [ensure-podman : Find distribution installation]
2025-10-02 00:14:21.839710 | controller | ok: "/var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-02 00:14:21.850418 | controller | included: /var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-02 00:14:21.856976 | 
2025-10-02 00:14:21.857043 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-02 00:15:35.762764 | controller | changed
2025-10-02 00:15:35.776270 | 
2025-10-02 00:15:35.776407 | TASK [ensure-podman : Fetch podman version]
2025-10-02 00:15:36.502497 | controller | Client:       Podman Engine
2025-10-02 00:15:36.528510 | controller | Version:      4.6.2
2025-10-02 00:15:36.528561 | controller | API Version:  4.6.2
2025-10-02 00:15:36.528595 | controller | Go Version:   go1.19.12
2025-10-02 00:15:36.528622 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-02 00:15:36.528631 | controller | OS/Arch:      linux/amd64
2025-10-02 00:15:36.929598 | controller | ok: Runtime: 0:00:00.208903
2025-10-02 00:15:36.942842 | 
2025-10-02 00:15:36.942990 | TASK [ensure-podman : Print podman version installed]
2025-10-02 00:15:36.982813 | Podman version: Client:       Podman Engine
2025-10-02 00:15:36.983050 | Version:      4.6.2
2025-10-02 00:15:36.983112 | API Version:  4.6.2
2025-10-02 00:15:36.983156 | Go Version:   go1.19.12
2025-10-02 00:15:36.983198 | Built:        Mon Aug 28 19:38:31 2023
2025-10-02 00:15:36.983242 | OS/Arch:      linux/amd64
2025-10-02 00:15:36.995227 | 
2025-10-02 00:15:36.995355 | TASK [ensure-podman : Validate podman engine]
2025-10-02 00:15:37.140126 | controller | skipping: Conditional result was False
2025-10-02 00:15:37.148824 | 
2025-10-02 00:15:37.148916 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-02 00:15:37.174313 | controller | skipping: Conditional result was False
2025-10-02 00:15:37.188501 | 
2025-10-02 00:15:37.188588 | TASK [Ensure python3.8 is present]
2025-10-02 00:15:37.213796 | controller | skipping: Conditional result was False
2025-10-02 00:15:37.221368 | 
2025-10-02 00:15:37.221472 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-02 00:15:37.244989 | controller | ok
2025-10-02 00:15:37.271497 | 
2025-10-02 00:15:37.271600 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-02 00:15:40.897384 | controller | ok: Nothing to do
2025-10-02 00:15:40.909817 | 
2025-10-02 00:15:40.909960 | TASK [our-ensure-python : Also install python3-devel]
2025-10-02 00:15:54.108357 | controller | changed
2025-10-02 00:15:54.119542 | 
2025-10-02 00:15:54.119619 | TASK [Run ensure-virtualenv role]
2025-10-02 00:15:54.140136 | controller | ok
2025-10-02 00:15:54.163442 | 
2025-10-02 00:15:54.163571 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-02 00:15:54.581543 | controller | /usr/bin/virtualenv
2025-10-02 00:15:54.831860 | controller | ok: Runtime: 0:00:00.004314
2025-10-02 00:15:54.845552 | 
2025-10-02 00:15:54.845747 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-02 00:15:54.884557 | controller | skipping: Conditional result was False
2025-10-02 00:15:54.884883 | controller | ok: All items complete
2025-10-02 00:15:54.884912 | 
2025-10-02 00:15:54.934798 | 
2025-10-02 00:15:54.935062 | TASK [Find the full path of the Python interpreter]
2025-10-02 00:15:55.379330 | controller | /usr/bin/python3
2025-10-02 00:15:55.571812 | controller | ok
2025-10-02 00:15:55.583583 | 
2025-10-02 00:15:55.583770 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-02 00:15:57.019777 | controller | created virtual environment CPython3.11.0.final.0-64 in 782ms
2025-10-02 00:15:57.075627 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-02 00:15:57.076024 | 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-02 00:15:57.076046 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-02 00:15:57.076069 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-02 00:15:57.236561 | controller | changed
2025-10-02 00:15:57.246259 | 
2025-10-02 00:15:57.246371 | TASK [Set selinux package]
2025-10-02 00:15:57.284711 | controller | ok
2025-10-02 00:15:57.294895 | 
2025-10-02 00:15:57.295022 | TASK [Set selinux package (Fedora)]
2025-10-02 00:15:57.337975 | controller | ok
2025-10-02 00:15:57.345661 | 
2025-10-02 00:15:57.345790 | TASK [Install selinux into virtualenv]
2025-10-02 00:15:59.971158 | controller | Collecting selinux-please-lie-to-me
2025-10-02 00:16:00.070013 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-02 00:16:00.601612 | controller | Collecting setuptools<50.0.0
2025-10-02 00:16:00.616513 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-02 00:16:00.757444 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.1 MB/s eta 0:00:00
2025-10-02 00:16:00.910334 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-02 00:16:00.910768 | controller |   Attempting uninstall: setuptools
2025-10-02 00:16:00.915742 | controller |     Found existing installation: setuptools 62.6.0
2025-10-02 00:16:01.027712 | controller |     Uninstalling setuptools-62.6.0:
2025-10-02 00:16:01.043082 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-02 00:16:01.809402 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-02 00:16:02.047844 | controller |
2025-10-02 00:16:02.286812 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-02 00:16:02.286858 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-02 00:16:02.580845 | controller | ok: Runtime: 0:00:04.467083
2025-10-02 00:16:02.593458 | 
2025-10-02 00:16:02.593597 | TASK [Install pytest-forked into virtualenv]
2025-10-02 00:16:03.836847 | controller | Collecting pytest-forked
2025-10-02 00:16:03.922967 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-02 00:16:03.988607 | controller | Collecting py
2025-10-02 00:16:04.001343 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-02 00:16:04.038001 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-10-02 00:16:04.213397 | controller | Collecting pytest>=3.10
2025-10-02 00:16:04.226378 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-02 00:16:04.293565 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.7 MB/s eta 0:00:00
2025-10-02 00:16:04.348764 | controller | Collecting iniconfig>=1
2025-10-02 00:16:04.361932 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-02 00:16:04.430535 | controller | Collecting packaging>=20
2025-10-02 00:16:04.443424 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-02 00:16:04.456300 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.1 MB/s eta 0:00:00
2025-10-02 00:16:04.502271 | controller | Collecting pluggy<2,>=1.5
2025-10-02 00:16:04.514977 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-02 00:16:04.588332 | controller | Collecting pygments>=2.7.2
2025-10-02 00:16:04.601107 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-02 00:16:04.732199 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.5 MB/s eta 0:00:00
2025-10-02 00:16:04.864034 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-02 00:16:07.117291 | 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-02 00:16:07.133195 | controller |
2025-10-02 00:16:07.318834 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-02 00:16:07.318886 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-02 00:16:07.771435 | controller | ok: Runtime: 0:00:04.214239
2025-10-02 00:16:07.779585 | 
2025-10-02 00:16:07.779743 | TASK [Update pip]
2025-10-02 00:16:08.858205 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-02 00:16:09.157904 | controller | Collecting pip
2025-10-02 00:16:09.259260 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-02 00:16:09.439639 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.9 MB/s eta 0:00:00
2025-10-02 00:16:09.600837 | controller | Installing collected packages: pip
2025-10-02 00:16:09.601138 | controller |   Attempting uninstall: pip
2025-10-02 00:16:09.606986 | controller |     Found existing installation: pip 22.2.2
2025-10-02 00:16:09.894293 | controller |     Uninstalling pip-22.2.2:
2025-10-02 00:16:09.923809 | controller |       Successfully uninstalled pip-22.2.2
2025-10-02 00:16:11.617008 | controller | Successfully installed pip-25.2
2025-10-02 00:16:11.926450 | controller | ok: Runtime: 0:00:03.549042
2025-10-02 00:16:11.939314 | 
2025-10-02 00:16:11.939474 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-02 00:16:12.470135 | controller | changed
2025-10-02 00:16:12.481969 | 
2025-10-02 00:16:12.482126 | TASK [Install ansible into virtualenv]
2025-10-02 00:16:13.556176 | controller | Processing ./src/github.com/ansible/ansible
2025-10-02 00:16:13.562690 | controller |   Installing build dependencies: started
2025-10-02 00:16:15.465973 | controller |   Installing build dependencies: finished with status 'done'
2025-10-02 00:16:15.469637 | controller |   Getting requirements to build wheel: started
2025-10-02 00:16:16.998655 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-02 00:16:17.909794 | controller |   Preparing metadata (pyproject.toml): started
2025-10-02 00:16:17.909840 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-02 00:16:17.914648 | 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-02 00:16:17.919285 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-02 00:16:18.149238 | controller | ERROR
2025-10-02 00:16:18.149493 | controller | {
2025-10-02 00:16:18.149554 | controller |   "delta": "0:00:05.131411",
2025-10-02 00:16:18.149596 | controller |   "end": "2025-10-02 00:16:18.069010",
2025-10-02 00:16:18.149634 | controller |   "msg": "non-zero return code",
2025-10-02 00:16:18.149768 | controller |   "rc": 1,
2025-10-02 00:16:18.149833 | controller |   "start": "2025-10-02 00:16:12.937599"
2025-10-02 00:16:18.149872 | controller | }
failure
2025-10-02 00:16:18.152950 | 
2025-10-02 00:16:18.153051 | PLAY RECAP
2025-10-02 00:16:18.153136 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-02 00:16:18.153179 | 
2025-10-02 00:16:18.275628 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-02 00:16:18.277129 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 00:16:18.877348 | 
2025-10-02 00:16:18.877493 | PLAY [all]
2025-10-02 00:16:18.898010 | 
2025-10-02 00:16:18.898094 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-02 00:16:19.711693 | controller | changed: non-zero return code
2025-10-02 00:16:19.723945 | 
2025-10-02 00:16:19.724105 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-02 00:16:19.752133 | controller | skipping: Conditional result was False
2025-10-02 00:16:19.764874 | 
2025-10-02 00:16:19.765023 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-02 00:16:19.806575 | 
2025-10-02 00:16:19.806918 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-02 00:16:19.847262 | 
2025-10-02 00:16:19.847564 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-02 00:16:19.875435 | controller | skipping: Conditional result was False
2025-10-02 00:16:19.888385 | 
2025-10-02 00:16:19.888535 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-02 00:16:19.930350 | 
2025-10-02 00:16:19.930609 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-02 00:16:19.958370 | controller | skipping: Conditional result was False
2025-10-02 00:16:19.972763 | 
2025-10-02 00:16:19.972909 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-02 00:16:20.000108 | controller | skipping: Conditional result was False
2025-10-02 00:16:20.012522 | 
2025-10-02 00:16:20.012701 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-02 00:16:20.040337 | controller | skipping: Conditional result was False
2025-10-02 00:16:20.089217 | 
2025-10-02 00:16:20.089342 | PLAY RECAP
2025-10-02 00:16:20.089401 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-02 00:16:20.089431 | 
2025-10-02 00:16:20.212014 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 00:16:20.213943 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-02 00:16:20.799203 | 
2025-10-02 00:16:20.799328 | PLAY [all:!appliance*]
2025-10-02 00:16:20.820290 | 
2025-10-02 00:16:20.820414 | TASK [unregister the node]
2025-10-02 00:16:20.957435 | controller | skipping: Conditional result was False
2025-10-02 00:16:20.969097 | 
2025-10-02 00:16:20.969264 | TASK [include_role : fetch-output]
2025-10-02 00:16:21.017291 | controller | ok
2025-10-02 00:16:21.052631 | 
2025-10-02 00:16:21.052778 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-02 00:16:21.119387 | controller | skipping: Conditional result was False
2025-10-02 00:16:21.131706 | 
2025-10-02 00:16:21.131858 | TASK [fetch-output : Set log path for single node]
2025-10-02 00:16:21.179738 | controller | ok
2025-10-02 00:16:21.191160 | 
2025-10-02 00:16:21.191297 | LOOP [fetch-output : Ensure local output dirs]
2025-10-02 00:16:21.631596 | controller -> localhost | ok: "/var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/logs"
2025-10-02 00:16:21.876731 | controller -> localhost | changed: "/var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/artifacts"
2025-10-02 00:16:22.155394 | controller -> localhost | changed: "/var/lib/zuul/builds/f50de31893f14eff8f19187998d0c538/work/docs"
2025-10-02 00:16:22.176637 | 
2025-10-02 00:16:22.176843 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-02 00:16:23.365921 | controller | changed:
2025-10-02 00:16:23.366247 | controller | .d..t...... ./
2025-10-02 00:16:23.366306 | controller | cd+++++++++ controller/
2025-10-02 00:16:23.366378 | controller | changed: All items complete
2025-10-02 00:16:23.366426 | 
2025-10-02 00:16:24.651557 | controller | changed: .d..t...... ./
2025-10-02 00:16:25.756511 | controller | changed: .d..t...... ./
2025-10-02 00:16:25.775638 | 
2025-10-02 00:16:25.775802 | TASK [include_role : fetch-output-openshift]
2025-10-02 00:16:25.800311 | controller | skipping: Conditional result was False
2025-10-02 00:16:25.806528 | 
2025-10-02 00:16:25.806595 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-02 00:16:25.854359 | controller | skipping: Conditional result was False
2025-10-02 00:16:25.865174 | controller | skipping: Conditional result was False
2025-10-02 00:16:25.901642 | 
2025-10-02 00:16:25.901783 | PLAY [localhost]
2025-10-02 00:16:25.915262 | 
2025-10-02 00:16:25.915340 | TASK [Run Zuul manifest role]
2025-10-02 00:16:25.935027 | localhost | ok
2025-10-02 00:16:25.949424 | 
2025-10-02 00:16:25.949505 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-02 00:16:26.380039 | localhost | changed
2025-10-02 00:16:26.389898 | 
2025-10-02 00:16:26.390032 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-02 00:16:26.436328 | localhost | ok
2025-10-02 00:16:26.454976 | 
2025-10-02 00:16:26.455103 | TASK [Set zuul-log-path fact]
2025-10-02 00:16:26.477990 | localhost | ok
2025-10-02 00:16:26.496643 | 
2025-10-02 00:16:26.496764 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 00:16:26.536863 | localhost | ok
2025-10-02 00:16:26.552405 | 
2025-10-02 00:16:26.552709 | LOOP [Run upload-logs-swift role]
2025-10-02 00:16:26.579905 | localhost | Output suppressed because no_log was given
2025-10-02 00:16:26.628349 | 
2025-10-02 00:16:26.628456 | TASK [Set zuul-log-path fact]
2025-10-02 00:16:26.663747 | localhost | skipping: Conditional result was False
2025-10-02 00:16:26.670774 | 
2025-10-02 00:16:26.670863 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-02 00:16:27.197248 | localhost -> localhost | ok: Runtime: 0:00:00.009007
2025-10-02 00:16:27.202522 | 
2025-10-02 00:16:27.202583 | TASK [upload-logs-swift : Upload logs to swift]