2025-10-22 00:06:40.494216 | Job console starting...
2025-10-22 00:06:40.506054 | Updating repositories
2025-10-22 00:06:41.417241 | Preparing job workspace
2025-10-22 00:06:49.595990 | Running Ansible setup...
2025-10-22 00:06:55.374242 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-22 00:06:56.009010 | 
2025-10-22 00:06:56.009122 | PLAY [localhost]
2025-10-22 00:06:56.017303 | 
2025-10-22 00:06:56.017370 | TASK [Gathering Facts]
2025-10-22 00:06:57.013813 | localhost | ok
2025-10-22 00:06:57.031917 | 
2025-10-22 00:06:57.032067 | TASK [Setup log path fact]
2025-10-22 00:06:57.054750 | localhost | ok
2025-10-22 00:06:57.074549 | 
2025-10-22 00:06:57.074716 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-22 00:06:57.106185 | localhost | ok
2025-10-22 00:06:57.117467 | 
2025-10-22 00:06:57.117591 | TASK [emit-job-header : Print job information]
2025-10-22 00:06:57.157214 | # Job Information
2025-10-22 00:06:57.157361 | Ansible Version: 2.15.12
2025-10-22 00:06:57.157394 | Job: ansible-test-sanity-docker-milestone
2025-10-22 00:06:57.157418 | Pipeline: periodic
2025-10-22 00:06:57.157438 | Executor: ze04.softwarefactory-project.io
2025-10-22 00:06:57.157458 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-22 00:06:57.157480 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/6be/ansible/6bea36f51b3b47a6821015841539360a/
2025-10-22 00:06:57.157500 | Event ID: 29cce05ecf284232acebc18c8d35e894
2025-10-22 00:06:57.161979 | 
2025-10-22 00:06:57.162072 | LOOP [emit-job-header : Print node information]
2025-10-22 00:06:57.263583 | localhost | ok:
2025-10-22 00:06:57.263739 | localhost | # Node Information
2025-10-22 00:06:57.263768 | localhost | Inventory Hostname: controller
2025-10-22 00:06:57.263789 | localhost | Hostname: ip-172-16-47-143
2025-10-22 00:06:57.263809 | localhost | Username: zuul-worker
2025-10-22 00:06:57.263830 | localhost | Distro: Fedora 37
2025-10-22 00:06:57.263849 | localhost | Provider: ansible-us-east-2
2025-10-22 00:06:57.263867 | localhost | Region: us-east-2
2025-10-22 00:06:57.263884 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-22 00:06:57.263901 | localhost | Product Name: t3.small
2025-10-22 00:06:57.263918 | localhost | Interface IP: 18.220.34.254
2025-10-22 00:06:57.275430 | 
2025-10-22 00:06:57.275508 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-22 00:06:57.696573 | localhost -> localhost | changed
2025-10-22 00:06:57.712774 | 
2025-10-22 00:06:57.712908 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-22 00:06:58.720819 | localhost -> localhost | changed
2025-10-22 00:06:58.750429 | 
2025-10-22 00:06:58.750528 | PLAY [all:!appliance*]
2025-10-22 00:06:58.769000 | 
2025-10-22 00:06:58.769159 | TASK [include_role : start-zuul-console]
2025-10-22 00:06:58.787781 | controller | ok
2025-10-22 00:06:58.804355 | 
2025-10-22 00:06:58.804444 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-22 00:06:59.544673 | controller | ok
2025-10-22 00:06:59.562864 | 
2025-10-22 00:06:59.562975 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-22 00:07:01.122964 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-22 00:07:01.132795 | 
2025-10-22 00:07:01.132928 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-22 00:07:01.288111 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.303228 | 
2025-10-22 00:07:01.303384 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-22 00:07:01.331221 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.346630 | 
2025-10-22 00:07:01.346878 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-22 00:07:01.374974 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.388731 | 
2025-10-22 00:07:01.388879 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-22 00:07:01.416655 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.425499 | 
2025-10-22 00:07:01.425598 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-22 00:07:01.441260 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.450515 | 
2025-10-22 00:07:01.450610 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-22 00:07:01.484118 | controller | skipping: Conditional result was False
2025-10-22 00:07:01.514171 | 
2025-10-22 00:07:01.514308 | TASK [Disable Fedora Modular]
2025-10-22 00:07:02.338779 | controller | changed
2025-10-22 00:07:02.351667 | 
2025-10-22 00:07:02.351837 | TASK [Enable EPEL]
2025-10-22 00:07:02.379799 | controller | skipping: Conditional result was False
2025-10-22 00:07:02.391470 | 
2025-10-22 00:07:02.391606 | TASK [Register the RHEL node]
2025-10-22 00:07:02.553062 | 
2025-10-22 00:07:02.553233 | TASK [Show the subscription-manager status]
2025-10-22 00:07:02.740945 | controller | skipping: Conditional result was False
2025-10-22 00:07:02.749725 | 
2025-10-22 00:07:02.749817 | TASK [Enable EPEL on RHEL]
2025-10-22 00:07:02.899190 | controller | skipping: Conditional result was False
2025-10-22 00:07:02.908842 | 
2025-10-22 00:07:02.908950 | TASK [Install git and tox]
2025-10-22 00:08:27.498063 | controller | changed
2025-10-22 00:08:27.508450 | 
2025-10-22 00:08:27.508559 | TASK [include_role : prepare-workspace]
2025-10-22 00:08:27.532172 | controller | ok
2025-10-22 00:08:27.565375 | 
2025-10-22 00:08:27.565503 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-22 00:08:28.196389 | controller | ok
2025-10-22 00:08:28.211778 | 
2025-10-22 00:08:28.212154 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-22 00:08:46.006579 | controller | Output suppressed because no_log was given
2025-10-22 00:08:46.020327 | 
2025-10-22 00:08:46.020452 | TASK [include_role : prepare-workspace-openshift]
2025-10-22 00:08:46.036386 | controller | skipping: Conditional result was False
2025-10-22 00:08:46.059598 | 
2025-10-22 00:08:46.059731 | PLAY [all:!appliance]
2025-10-22 00:08:46.098950 | 
2025-10-22 00:08:46.099058 | TASK [Run add-build-sshkey role (RSA)]
2025-10-22 00:08:46.127992 | controller | ok
2025-10-22 00:08:46.143431 | 
2025-10-22 00:08:46.143512 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-22 00:08:46.401548 | controller -> localhost | ok
2025-10-22 00:08:46.412224 | 
2025-10-22 00:08:46.412352 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-22 00:08:46.437203 | controller | ok
2025-10-22 00:08:46.462535 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-22 00:08:46.471253 | 
2025-10-22 00:08:46.471341 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-22 00:08:47.071414 | controller -> localhost | Generating public/private rsa key pair.
2025-10-22 00:08:47.071835 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_rsa.
2025-10-22 00:08:47.071910 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_rsa.pub.
2025-10-22 00:08:47.071959 | controller -> localhost | The key fingerprint is:
2025-10-22 00:08:47.072003 | controller -> localhost | SHA256:Ln+nU4jU1AHSjjezT1e8tQu94GYp5nJi2o0h0puHHa8 zuul-build-sshkey
2025-10-22 00:08:47.072051 | controller -> localhost | The key's randomart image is:
2025-10-22 00:08:47.072095 | controller -> localhost | +---[RSA 2048]----+
2025-10-22 00:08:47.072136 | controller -> localhost | |        ...o..   |
2025-10-22 00:08:47.072179 | controller -> localhost | |         .o .    |
2025-10-22 00:08:47.072220 | controller -> localhost | |         =     . |
2025-10-22 00:08:47.072261 | controller -> localhost | |        o *     +|
2025-10-22 00:08:47.072300 | controller -> localhost | |       .So =  ..+|
2025-10-22 00:08:47.072358 | controller -> localhost | |      ....o oo.+ |
2025-10-22 00:08:47.072406 | controller -> localhost | |     ..o+.o+..+ o|
2025-10-22 00:08:47.072449 | controller -> localhost | |      .+=**=o= o |
2025-10-22 00:08:47.072490 | controller -> localhost | |       +=EO*+    |
2025-10-22 00:08:47.072537 | controller -> localhost | +----[SHA256]-----+
2025-10-22 00:08:47.072635 | controller -> localhost | ok: Runtime: 0:00:00.160718
2025-10-22 00:08:47.083366 | 
2025-10-22 00:08:47.083501 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-22 00:08:47.120148 | controller | ok
2025-10-22 00:08:47.135075 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-22 00:08:47.149347 | 
2025-10-22 00:08:47.149499 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-22 00:08:47.175757 | controller | skipping: Conditional result was False
2025-10-22 00:08:47.191148 | 
2025-10-22 00:08:47.191293 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-22 00:08:47.855647 | controller | changed
2025-10-22 00:08:47.869474 | 
2025-10-22 00:08:47.869669 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-22 00:08:48.239826 | controller | ok
2025-10-22 00:08:48.248649 | 
2025-10-22 00:08:48.248815 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-22 00:08:49.618633 | controller | changed
2025-10-22 00:08:49.627800 | 
2025-10-22 00:08:49.627932 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-22 00:08:51.067955 | controller | changed
2025-10-22 00:08:51.073943 | 
2025-10-22 00:08:51.074011 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-22 00:08:51.088435 | controller | skipping: Conditional result was False
2025-10-22 00:08:51.097436 | 
2025-10-22 00:08:51.097538 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-22 00:08:51.540302 | controller -> localhost | changed
2025-10-22 00:08:51.552641 | 
2025-10-22 00:08:51.552749 | TASK [add-build-sshkey : Add back temp key]
2025-10-22 00:08:51.872709 | controller -> localhost | Identity added: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_rsa (zuul-build-sshkey)
2025-10-22 00:08:51.872963 | controller -> localhost | ok: Runtime: 0:00:00.007262
2025-10-22 00:08:51.879347 | 
2025-10-22 00:08:51.879413 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-22 00:08:52.389900 | controller | ok
2025-10-22 00:08:52.402587 | 
2025-10-22 00:08:52.402769 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-22 00:08:52.430062 | controller | skipping: Conditional result was False
2025-10-22 00:08:52.456611 | 
2025-10-22 00:08:52.456862 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-22 00:08:52.483764 | controller | ok
2025-10-22 00:08:52.507343 | 
2025-10-22 00:08:52.507452 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-22 00:08:52.747241 | controller -> localhost | ok
2025-10-22 00:08:52.756587 | 
2025-10-22 00:08:52.756728 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-22 00:08:52.792044 | controller | ok
2025-10-22 00:08:52.815033 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-22 00:08:52.823212 | 
2025-10-22 00:08:52.823301 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-22 00:08:53.145122 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-22 00:08:53.145362 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_ecdsa.
2025-10-22 00:08:53.145403 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_ecdsa.pub.
2025-10-22 00:08:53.145449 | controller -> localhost | The key fingerprint is:
2025-10-22 00:08:53.145479 | controller -> localhost | SHA256:M0bFB6O27OuLAb/Bp/KYrsfLCuO2H7kGHjtSisoVYHQ zuul-build-sshkey
2025-10-22 00:08:53.145508 | controller -> localhost | The key's randomart image is:
2025-10-22 00:08:53.145557 | controller -> localhost | +---[ECDSA 521]---+
2025-10-22 00:08:53.145614 | controller -> localhost | | . E     .+.     |
2025-10-22 00:08:53.145647 | controller -> localhost | |. .      o...    |
2025-10-22 00:08:53.145706 | controller -> localhost | | o      +  .     |
2025-10-22 00:08:53.145745 | controller -> localhost | |. .    + .       |
2025-10-22 00:08:53.145773 | controller -> localhost | |   ..   S        |
2025-10-22 00:08:53.145799 | controller -> localhost | | o. o+ o o       |
2025-10-22 00:08:53.145823 | controller -> localhost | |=o+=  = o        |
2025-10-22 00:08:53.145850 | controller -> localhost | |*B.o*o B .       |
2025-10-22 00:08:53.145874 | controller -> localhost | |=+BB*+=.+.       |
2025-10-22 00:08:53.145898 | controller -> localhost | +----[SHA256]-----+
2025-10-22 00:08:53.145965 | controller -> localhost | ok: Runtime: 0:00:00.010319
2025-10-22 00:08:53.156595 | 
2025-10-22 00:08:53.156764 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-22 00:08:53.197286 | controller | ok
2025-10-22 00:08:53.214837 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-22 00:08:53.234278 | 
2025-10-22 00:08:53.234466 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-22 00:08:53.250951 | controller | skipping: Conditional result was False
2025-10-22 00:08:53.257898 | 
2025-10-22 00:08:53.257966 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-22 00:08:53.715408 | controller | changed
2025-10-22 00:08:53.723714 | 
2025-10-22 00:08:53.723828 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-22 00:08:54.078034 | controller | ok
2025-10-22 00:08:54.085765 | 
2025-10-22 00:08:54.085861 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-22 00:08:55.443074 | controller | changed
2025-10-22 00:08:55.456516 | 
2025-10-22 00:08:55.456666 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-22 00:08:57.048855 | controller | changed
2025-10-22 00:08:57.055108 | 
2025-10-22 00:08:57.055214 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-22 00:08:57.078876 | controller | skipping: Conditional result was False
2025-10-22 00:08:57.084871 | 
2025-10-22 00:08:57.084949 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-22 00:08:57.342942 | controller -> localhost | changed
2025-10-22 00:08:57.355107 | 
2025-10-22 00:08:57.355241 | TASK [add-build-sshkey : Add back temp key]
2025-10-22 00:08:57.669208 | controller -> localhost | Identity added: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/6bea36f51b3b47a6821015841539360a_id_ecdsa (zuul-build-sshkey)
2025-10-22 00:08:57.669768 | controller -> localhost | ok: Runtime: 0:00:00.013546
2025-10-22 00:08:57.685374 | 
2025-10-22 00:08:57.685558 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-22 00:08:58.044930 | controller | ok
2025-10-22 00:08:58.098586 | 
2025-10-22 00:08:58.098790 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-22 00:08:58.135165 | controller | skipping: Conditional result was False
2025-10-22 00:08:58.152868 | 
2025-10-22 00:08:58.153002 | TASK [include_role : remove-zuul-sshkey]
2025-10-22 00:08:58.178542 | controller | skipping: Conditional result was False
2025-10-22 00:08:58.188411 | 
2025-10-22 00:08:58.188532 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-22 00:08:58.533325 | controller | ok: "logs"
2025-10-22 00:08:58.533656 | controller | ok: All items complete
2025-10-22 00:08:58.533743 | 
2025-10-22 00:08:58.825157 | controller | ok: "artifacts"
2025-10-22 00:08:59.123966 | controller | ok: "docs"
2025-10-22 00:08:59.147576 | 
2025-10-22 00:08:59.147791 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-22 00:08:59.511588 | controller | changed: "logs"
2025-10-22 00:08:59.801560 | controller | changed: "artifacts"
2025-10-22 00:09:00.148501 | controller | changed: "docs"
2025-10-22 00:09:00.210007 | 
2025-10-22 00:09:00.210131 | PLAY RECAP
2025-10-22 00:09:00.210196 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-22 00:09:00.210234 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-22 00:09:00.210261 | 
2025-10-22 00:09:00.332640 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-22 00:09:00.333487 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-22 00:09:00.945511 | 
2025-10-22 00:09:00.945652 | PLAY [all]
2025-10-22 00:09:00.970659 | 
2025-10-22 00:09:00.970825 | TASK [Install binary dependencies]
2025-10-22 00:09:01.021760 | controller | ok
2025-10-22 00:09:01.045020 | 
2025-10-22 00:09:01.045192 | TASK [bindep : Include find tasks]
2025-10-22 00:09:01.075273 | controller | ok
2025-10-22 00:09:01.084035 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-22 00:09:01.090952 | 
2025-10-22 00:09:01.091071 | TASK [bindep : Look for bindep.txt]
2025-10-22 00:09:02.080590 | controller | ok
2025-10-22 00:09:02.094994 | 
2025-10-22 00:09:02.095189 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:09:02.123243 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.143367 | 
2025-10-22 00:09:02.143602 | TASK [bindep : Look for other-requirements.txt]
2025-10-22 00:09:02.678018 | controller | ok
2025-10-22 00:09:02.691130 | 
2025-10-22 00:09:02.691337 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:09:02.729991 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.740817 | 
2025-10-22 00:09:02.740960 | TASK [bindep : Look for bindep fallback file]
2025-10-22 00:09:02.778398 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.787715 | 
2025-10-22 00:09:02.787824 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:09:02.815106 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.824254 | 
2025-10-22 00:09:02.824331 | TASK [bindep : Include bindep tasks]
2025-10-22 00:09:02.849515 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.859560 | 
2025-10-22 00:09:02.859721 | TASK [bindep : Include install tasks]
2025-10-22 00:09:02.885876 | controller | skipping: Conditional result was False
2025-10-22 00:09:02.893189 | 
2025-10-22 00:09:02.893260 | LOOP [bindep : Include package tasks]
2025-10-22 00:09:02.948882 | 
2025-10-22 00:09:02.949027 | TASK [Run test-setup role]
2025-10-22 00:09:02.972907 | controller | ok
2025-10-22 00:09:02.999861 | 
2025-10-22 00:09:02.999957 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-22 00:09:03.486811 | controller | ok
2025-10-22 00:09:03.502162 | 
2025-10-22 00:09:03.502386 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-22 00:09:03.658279 | controller | skipping: Conditional result was False
2025-10-22 00:09:03.711116 | 
2025-10-22 00:09:03.711236 | PLAY RECAP
2025-10-22 00:09:03.711292 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-22 00:09:03.711320 | 
2025-10-22 00:09:03.811720 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-22 00:09:03.813661 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-22 00:09:04.426112 | 
2025-10-22 00:09:04.426234 | PLAY [controller]
2025-10-22 00:09:04.445525 | 
2025-10-22 00:09:04.445641 | TASK [Create the /root directory]
2025-10-22 00:09:05.206209 | controller | ok
2025-10-22 00:09:05.218392 | 
2025-10-22 00:09:05.218547 | TASK [Install glibc-langpack-en]
2025-10-22 00:09:13.150542 | controller | ok: Nothing to do
2025-10-22 00:09:13.158590 | 
2025-10-22 00:09:13.158769 | TASK [Ensure controller directory exists]
2025-10-22 00:09:13.673953 | controller | changed
2025-10-22 00:09:13.681387 | 
2025-10-22 00:09:13.681516 | TASK [Install container runtime]
2025-10-22 00:09:13.734751 | controller | ok
2025-10-22 00:09:13.784947 | 
2025-10-22 00:09:13.785104 | LOOP [ensure-podman : Find distribution installation]
2025-10-22 00:09:13.828815 | controller | ok: "/var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-22 00:09:13.842217 | controller | included: /var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-22 00:09:13.852633 | 
2025-10-22 00:09:13.852787 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-22 00:10:24.303135 | controller | changed
2025-10-22 00:10:24.310651 | 
2025-10-22 00:10:24.310781 | TASK [ensure-podman : Fetch podman version]
2025-10-22 00:10:25.135013 | controller | Client:       Podman Engine
2025-10-22 00:10:25.135090 | controller | Version:      4.6.2
2025-10-22 00:10:25.135135 | controller | API Version:  4.6.2
2025-10-22 00:10:25.135170 | controller | Go Version:   go1.19.12
2025-10-22 00:10:25.164954 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-22 00:10:25.164992 | controller | OS/Arch:      linux/amd64
2025-10-22 00:10:25.484526 | controller | ok: Runtime: 0:00:00.215215
2025-10-22 00:10:25.491404 | 
2025-10-22 00:10:25.491505 | TASK [ensure-podman : Print podman version installed]
2025-10-22 00:10:25.521623 | Podman version: Client:       Podman Engine
2025-10-22 00:10:25.521818 | Version:      4.6.2
2025-10-22 00:10:25.521850 | API Version:  4.6.2
2025-10-22 00:10:25.521871 | Go Version:   go1.19.12
2025-10-22 00:10:25.521890 | Built:        Mon Aug 28 19:38:31 2023
2025-10-22 00:10:25.521908 | OS/Arch:      linux/amd64
2025-10-22 00:10:25.528159 | 
2025-10-22 00:10:25.528259 | TASK [ensure-podman : Validate podman engine]
2025-10-22 00:10:25.669229 | controller | skipping: Conditional result was False
2025-10-22 00:10:25.676103 | 
2025-10-22 00:10:25.676193 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-22 00:10:25.690040 | controller | skipping: Conditional result was False
2025-10-22 00:10:25.702766 | 
2025-10-22 00:10:25.702883 | TASK [Ensure python3.8 is present]
2025-10-22 00:10:25.721781 | controller | skipping: Conditional result was False
2025-10-22 00:10:25.730725 | 
2025-10-22 00:10:25.730862 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-22 00:10:25.756919 | controller | ok
2025-10-22 00:10:25.782137 | 
2025-10-22 00:10:25.782274 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-22 00:10:29.530262 | controller | ok: Nothing to do
2025-10-22 00:10:29.548888 | 
2025-10-22 00:10:29.549025 | TASK [our-ensure-python : Also install python3-devel]
2025-10-22 00:10:42.120385 | controller | changed
2025-10-22 00:10:42.142576 | 
2025-10-22 00:10:42.142780 | TASK [Run ensure-virtualenv role]
2025-10-22 00:10:42.170382 | controller | ok
2025-10-22 00:10:42.207188 | 
2025-10-22 00:10:42.207386 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-22 00:10:42.608108 | controller | /usr/bin/virtualenv
2025-10-22 00:10:43.507857 | controller | ok: Runtime: 0:00:00.003961
2025-10-22 00:10:43.541864 | 
2025-10-22 00:10:43.542117 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-22 00:10:43.577244 | controller | skipping: Conditional result was False
2025-10-22 00:10:43.577597 | controller | ok: All items complete
2025-10-22 00:10:43.577637 | 
2025-10-22 00:10:43.685410 | 
2025-10-22 00:10:43.685633 | TASK [Find the full path of the Python interpreter]
2025-10-22 00:10:44.195567 | controller | /usr/bin/python3
2025-10-22 00:10:44.326634 | controller | ok
2025-10-22 00:10:44.333480 | 
2025-10-22 00:10:44.333582 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-22 00:10:45.770376 | controller | created virtual environment CPython3.11.0.final.0-64 in 781ms
2025-10-22 00:10:45.812846 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-22 00:10:45.812900 | 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-22 00:10:45.812913 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-22 00:10:45.812937 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-22 00:10:45.982392 | controller | changed
2025-10-22 00:10:46.016116 | 
2025-10-22 00:10:46.016242 | TASK [Set selinux package]
2025-10-22 00:10:46.053124 | controller | ok
2025-10-22 00:10:46.064484 | 
2025-10-22 00:10:46.064596 | TASK [Set selinux package (Fedora)]
2025-10-22 00:10:46.121010 | controller | ok
2025-10-22 00:10:46.127023 | 
2025-10-22 00:10:46.127114 | TASK [Install selinux into virtualenv]
2025-10-22 00:10:48.714764 | controller | Collecting selinux-please-lie-to-me
2025-10-22 00:10:48.809805 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-22 00:10:49.334932 | controller | Collecting setuptools<50.0.0
2025-10-22 00:10:49.348242 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-22 00:10:49.470417 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-10-22 00:10:49.622500 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-22 00:10:49.622887 | controller |   Attempting uninstall: setuptools
2025-10-22 00:10:49.627699 | controller |     Found existing installation: setuptools 62.6.0
2025-10-22 00:10:49.736161 | controller |     Uninstalling setuptools-62.6.0:
2025-10-22 00:10:49.750937 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-22 00:10:50.479781 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-22 00:10:50.693626 | controller |
2025-10-22 00:10:50.889625 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-22 00:10:50.889672 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-22 00:10:51.289376 | controller | ok: Runtime: 0:00:04.273307
2025-10-22 00:10:51.296599 | 
2025-10-22 00:10:51.296735 | TASK [Install pytest-forked into virtualenv]
2025-10-22 00:10:52.460801 | controller | Collecting pytest-forked
2025-10-22 00:10:52.552747 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-22 00:10:52.609168 | controller | Collecting py
2025-10-22 00:10:52.621994 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-22 00:10:52.653771 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-10-22 00:10:52.821610 | controller | Collecting pytest>=3.10
2025-10-22 00:10:52.836922 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-22 00:10:52.882216 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.6 MB/s eta 0:00:00
2025-10-22 00:10:52.936952 | controller | Collecting iniconfig>=1
2025-10-22 00:10:52.948927 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-22 00:10:53.015556 | controller | Collecting packaging>=20
2025-10-22 00:10:53.027146 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-22 00:10:53.036918 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.2 MB/s eta 0:00:00
2025-10-22 00:10:53.081053 | controller | Collecting pluggy<2,>=1.5
2025-10-22 00:10:53.092246 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-22 00:10:53.165919 | controller | Collecting pygments>=2.7.2
2025-10-22 00:10:53.177704 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-22 00:10:53.260969 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 15.3 MB/s eta 0:00:00
2025-10-22 00:10:53.389737 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-22 00:10:55.546870 | controller | Successfully installed iniconfig-2.3.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-22 00:10:55.562273 | controller |
2025-10-22 00:10:55.774513 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-22 00:10:55.774562 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-22 00:10:55.971565 | controller | ok: Runtime: 0:00:04.012208
2025-10-22 00:10:55.977817 | 
2025-10-22 00:10:55.977901 | TASK [Update pip]
2025-10-22 00:10:57.044819 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-22 00:10:57.337690 | controller | Collecting pip
2025-10-22 00:10:57.422960 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-22 00:10:57.576177 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.7 MB/s eta 0:00:00
2025-10-22 00:10:57.731240 | controller | Installing collected packages: pip
2025-10-22 00:10:57.731953 | controller |   Attempting uninstall: pip
2025-10-22 00:10:57.738328 | controller |     Found existing installation: pip 22.2.2
2025-10-22 00:10:57.987795 | controller |     Uninstalling pip-22.2.2:
2025-10-22 00:10:58.017319 | controller |       Successfully uninstalled pip-22.2.2
2025-10-22 00:10:59.646495 | controller | Successfully installed pip-25.2
2025-10-22 00:11:00.126863 | controller | ok: Runtime: 0:00:03.342180
2025-10-22 00:11:00.134785 | 
2025-10-22 00:11:00.134921 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-22 00:11:00.643191 | controller | changed
2025-10-22 00:11:00.651414 | 
2025-10-22 00:11:00.651531 | TASK [Install ansible into virtualenv]
2025-10-22 00:11:01.662632 | controller | Processing ./src/github.com/ansible/ansible
2025-10-22 00:11:01.668909 | controller |   Installing build dependencies: started
2025-10-22 00:11:03.644617 | controller |   Installing build dependencies: finished with status 'done'
2025-10-22 00:11:05.205343 | controller |   Getting requirements to build wheel: started
2025-10-22 00:11:05.205409 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-22 00:11:05.206951 | controller |   Preparing metadata (pyproject.toml): started
2025-10-22 00:11:06.093355 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-22 00:11:06.097918 | 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-22 00:11:06.102655 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-22 00:11:06.334214 | controller | ERROR
2025-10-22 00:11:06.334462 | controller | {
2025-10-22 00:11:06.334517 | controller |   "delta": "0:00:05.184779",
2025-10-22 00:11:06.334550 | controller |   "end": "2025-10-22 00:11:06.241653",
2025-10-22 00:11:06.334582 | controller |   "msg": "non-zero return code",
2025-10-22 00:11:06.334626 | controller |   "rc": 1,
2025-10-22 00:11:06.334745 | controller |   "start": "2025-10-22 00:11:01.056874"
2025-10-22 00:11:06.334790 | controller | }
failure
2025-10-22 00:11:06.337071 | 
2025-10-22 00:11:06.337131 | PLAY RECAP
2025-10-22 00:11:06.337185 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-22 00:11:06.337217 | 
2025-10-22 00:11:06.513705 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-22 00:11:06.515225 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-22 00:11:07.234069 | 
2025-10-22 00:11:07.234211 | PLAY [all]
2025-10-22 00:11:07.257436 | 
2025-10-22 00:11:07.257585 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-22 00:11:08.088523 | controller | changed: non-zero return code
2025-10-22 00:11:08.095187 | 
2025-10-22 00:11:08.095342 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-22 00:11:08.121996 | controller | skipping: Conditional result was False
2025-10-22 00:11:08.129553 | 
2025-10-22 00:11:08.129739 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-22 00:11:08.165540 | 
2025-10-22 00:11:08.165815 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-22 00:11:08.199459 | 
2025-10-22 00:11:08.199714 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-22 00:11:08.247955 | controller | skipping: Conditional result was False
2025-10-22 00:11:08.258651 | 
2025-10-22 00:11:08.258981 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-22 00:11:08.309386 | 
2025-10-22 00:11:08.309740 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-22 00:11:08.339030 | controller | skipping: Conditional result was False
2025-10-22 00:11:08.350887 | 
2025-10-22 00:11:08.351115 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-22 00:11:08.380880 | controller | skipping: Conditional result was False
2025-10-22 00:11:08.387256 | 
2025-10-22 00:11:08.387373 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-22 00:11:08.412397 | controller | skipping: Conditional result was False
2025-10-22 00:11:08.440897 | 
2025-10-22 00:11:08.441003 | PLAY RECAP
2025-10-22 00:11:08.441044 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-22 00:11:08.441066 | 
2025-10-22 00:11:08.579464 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-22 00:11:08.580339 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-22 00:11:09.259892 | 
2025-10-22 00:11:09.260041 | PLAY [all:!appliance*]
2025-10-22 00:11:09.285719 | 
2025-10-22 00:11:09.285887 | TASK [unregister the node]
2025-10-22 00:11:09.427994 | controller | skipping: Conditional result was False
2025-10-22 00:11:09.438196 | 
2025-10-22 00:11:09.438436 | TASK [include_role : fetch-output]
2025-10-22 00:11:09.493667 | controller | ok
2025-10-22 00:11:09.534079 | 
2025-10-22 00:11:09.534300 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-22 00:11:09.623701 | controller | skipping: Conditional result was False
2025-10-22 00:11:09.634342 | 
2025-10-22 00:11:09.634539 | TASK [fetch-output : Set log path for single node]
2025-10-22 00:11:09.698183 | controller | ok
2025-10-22 00:11:09.706070 | 
2025-10-22 00:11:09.706168 | LOOP [fetch-output : Ensure local output dirs]
2025-10-22 00:11:10.198087 | controller -> localhost | ok: "/var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/logs"
2025-10-22 00:11:10.599432 | controller -> localhost | changed: "/var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/artifacts"
2025-10-22 00:11:10.957584 | controller -> localhost | changed: "/var/lib/zuul/builds/6bea36f51b3b47a6821015841539360a/work/docs"
2025-10-22 00:11:11.010136 | 
2025-10-22 00:11:11.010285 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-22 00:11:12.340275 | controller | changed:
2025-10-22 00:11:12.340537 | controller | .d..t...... ./
2025-10-22 00:11:12.340589 | controller | cd+++++++++ controller/
2025-10-22 00:11:12.340648 | controller | changed: All items complete
2025-10-22 00:11:12.340710 | 
2025-10-22 00:11:13.432376 | controller | changed: .d..t...... ./
2025-10-22 00:11:14.909743 | controller | changed: .d..t...... ./
2025-10-22 00:11:14.934227 | 
2025-10-22 00:11:14.934342 | TASK [include_role : fetch-output-openshift]
2025-10-22 00:11:14.949272 | controller | skipping: Conditional result was False
2025-10-22 00:11:14.957440 | 
2025-10-22 00:11:14.957540 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-22 00:11:14.984297 | controller | skipping: Conditional result was False
2025-10-22 00:11:14.992697 | controller | skipping: Conditional result was False
2025-10-22 00:11:15.031655 | 
2025-10-22 00:11:15.031757 | PLAY [localhost]
2025-10-22 00:11:15.045123 | 
2025-10-22 00:11:15.045952 | TASK [Run Zuul manifest role]
2025-10-22 00:11:15.068496 | localhost | ok
2025-10-22 00:11:15.083772 | 
2025-10-22 00:11:15.083908 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-22 00:11:15.611544 | localhost | changed
2025-10-22 00:11:15.625191 | 
2025-10-22 00:11:15.625287 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-22 00:11:15.666587 | localhost | ok
2025-10-22 00:11:15.678296 | 
2025-10-22 00:11:15.678365 | TASK [Set zuul-log-path fact]
2025-10-22 00:11:15.699117 | localhost | ok
2025-10-22 00:11:15.716581 | 
2025-10-22 00:11:15.716890 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-22 00:11:15.746611 | localhost | ok
2025-10-22 00:11:15.754988 | 
2025-10-22 00:11:15.755091 | LOOP [Run upload-logs-swift role]
2025-10-22 00:11:15.790253 | localhost | Output suppressed because no_log was given
2025-10-22 00:11:15.828990 | 
2025-10-22 00:11:15.829115 | TASK [Set zuul-log-path fact]
2025-10-22 00:11:15.873773 | localhost | skipping: Conditional result was False
2025-10-22 00:11:15.878981 | 
2025-10-22 00:11:15.879063 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-22 00:11:16.423307 | localhost -> localhost | ok: Runtime: 0:00:00.006668
2025-10-22 00:11:16.439719 | 
2025-10-22 00:11:16.439846 | TASK [upload-logs-swift : Upload logs to swift]