2026-01-09 00:06:34.614883 | Job console starting...
2026-01-09 00:06:34.624802 | Updating repositories
2026-01-09 00:06:34.784655 | Preparing job workspace
2026-01-09 00:06:44.760734 | Running Ansible setup...
2026-01-09 00:06:51.016004 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-09 00:06:51.816268 | 
2026-01-09 00:06:51.816404 | PLAY [localhost]
2026-01-09 00:06:51.825602 | 
2026-01-09 00:06:51.825697 | TASK [Gathering Facts]
2026-01-09 00:06:52.836472 | localhost | ok
2026-01-09 00:06:52.851817 | 
2026-01-09 00:06:52.851971 | TASK [Setup log path fact]
2026-01-09 00:06:52.881944 | localhost | ok
2026-01-09 00:06:52.895165 | 
2026-01-09 00:06:52.895264 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-09 00:06:52.926820 | localhost | ok
2026-01-09 00:06:52.936123 | 
2026-01-09 00:06:52.936245 | TASK [emit-job-header : Print job information]
2026-01-09 00:06:52.979174 | # Job Information
2026-01-09 00:06:52.979360 | Ansible Version: 2.15.12
2026-01-09 00:06:52.979393 | Job: ansible-test-sanity-docker-devel
2026-01-09 00:06:52.979413 | Pipeline: periodic
2026-01-09 00:06:52.979431 | Executor: ze01.softwarefactory-project.io
2026-01-09 00:06:52.979448 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-09 00:06:52.979468 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/b78/ansible/b78412301bb74216a5668f9ef71b2b31/
2026-01-09 00:06:52.979486 | Event ID: 985433d38163455aa42d913504b2dc7d
2026-01-09 00:06:52.983745 | 
2026-01-09 00:06:52.983818 | LOOP [emit-job-header : Print node information]
2026-01-09 00:06:53.122697 | localhost | ok:
2026-01-09 00:06:53.123368 | localhost | # Node Information
2026-01-09 00:06:53.123452 | localhost | Inventory Hostname: controller
2026-01-09 00:06:53.123497 | localhost | Hostname: np0005578766
2026-01-09 00:06:53.123539 | localhost | Username: zuul
2026-01-09 00:06:53.123586 | localhost | Distro: Fedora 37
2026-01-09 00:06:53.123628 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2026-01-09 00:06:53.123666 | localhost | Region: ca-ymq-1
2026-01-09 00:06:53.123702 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-09 00:06:53.123737 | localhost | Product Name: OpenStack Nova
2026-01-09 00:06:53.123773 | localhost | Interface IP: 162.253.55.212
2026-01-09 00:06:53.160478 | 
2026-01-09 00:06:53.160736 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-09 00:06:53.681437 | localhost -> localhost | changed
2026-01-09 00:06:53.692998 | 
2026-01-09 00:06:53.693225 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-09 00:06:54.875006 | localhost -> localhost | changed
2026-01-09 00:06:54.898990 | 
2026-01-09 00:06:54.899111 | PLAY [all:!appliance*]
2026-01-09 00:06:54.916700 | 
2026-01-09 00:06:54.916818 | TASK [include_role : start-zuul-console]
2026-01-09 00:06:54.936650 | controller | ok
2026-01-09 00:06:54.954945 | 
2026-01-09 00:06:54.955186 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-09 00:06:55.333223 | controller | ok
2026-01-09 00:06:55.354299 | 
2026-01-09 00:06:55.354471 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-09 00:06:56.247076 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-09 00:06:56.254791 | 
2026-01-09 00:06:56.254870 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-09 00:06:56.796367 | controller | skipping: Conditional result was False
2026-01-09 00:06:56.817745 | 
2026-01-09 00:06:56.817894 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-09 00:06:56.844108 | controller | skipping: Conditional result was False
2026-01-09 00:06:56.856315 | 
2026-01-09 00:06:56.856425 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-09 00:06:56.882722 | controller | skipping: Conditional result was False
2026-01-09 00:06:56.893580 | 
2026-01-09 00:06:56.893710 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-09 00:06:56.920517 | controller | skipping: Conditional result was False
2026-01-09 00:06:56.931369 | 
2026-01-09 00:06:56.931483 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-09 00:06:56.956623 | controller | skipping: Conditional result was False
2026-01-09 00:06:56.979099 | 
2026-01-09 00:06:56.979256 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-09 00:06:57.019133 | controller | skipping: Conditional result was False
2026-01-09 00:06:57.031495 | 
2026-01-09 00:06:57.031571 | TASK [Disable Fedora Modular]
2026-01-09 00:06:57.304895 | controller | changed
2026-01-09 00:06:57.320374 | 
2026-01-09 00:06:57.320592 | TASK [Enable EPEL]
2026-01-09 00:06:57.348435 | controller | skipping: Conditional result was False
2026-01-09 00:06:57.363784 | 
2026-01-09 00:06:57.363985 | TASK [Register the RHEL node]
2026-01-09 00:06:57.943853 | 
2026-01-09 00:06:57.944085 | TASK [Show the subscription-manager status]
2026-01-09 00:06:58.534750 | controller | skipping: Conditional result was False
2026-01-09 00:06:58.543466 | 
2026-01-09 00:06:58.543596 | TASK [Enable EPEL on RHEL]
2026-01-09 00:06:59.111561 | controller | skipping: Conditional result was False
2026-01-09 00:06:59.117639 | 
2026-01-09 00:06:59.117719 | TASK [Install git and tox]
2026-01-09 00:08:23.463072 | controller | changed
2026-01-09 00:08:23.480866 | 
2026-01-09 00:08:23.481054 | TASK [include_role : prepare-workspace]
2026-01-09 00:08:23.515235 | controller | ok
2026-01-09 00:08:23.550833 | 
2026-01-09 00:08:23.551039 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-09 00:08:23.804508 | controller | ok
2026-01-09 00:08:23.814718 | 
2026-01-09 00:08:23.814822 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-09 00:08:38.376470 | controller | Output suppressed because no_log was given
2026-01-09 00:08:38.451094 | 
2026-01-09 00:08:38.451236 | TASK [include_role : prepare-workspace-openshift]
2026-01-09 00:08:38.486793 | controller | skipping: Conditional result was False
2026-01-09 00:08:38.518218 | 
2026-01-09 00:08:38.518300 | PLAY [all:!appliance]
2026-01-09 00:08:38.534775 | 
2026-01-09 00:08:38.534872 | TASK [Run add-build-sshkey role (RSA)]
2026-01-09 00:08:38.575654 | controller | ok
2026-01-09 00:08:38.594841 | 
2026-01-09 00:08:38.594979 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-09 00:08:39.272633 | controller -> localhost | ok
2026-01-09 00:08:39.283826 | 
2026-01-09 00:08:39.283960 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-09 00:08:39.317592 | controller | ok
2026-01-09 00:08:39.339140 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-09 00:08:39.348587 | 
2026-01-09 00:08:39.348715 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-09 00:08:40.149672 | controller -> localhost | Generating public/private rsa key pair.
2026-01-09 00:08:40.149908 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_rsa.
2026-01-09 00:08:40.149947 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_rsa.pub.
2026-01-09 00:08:40.149977 | controller -> localhost | The key fingerprint is:
2026-01-09 00:08:40.150003 | controller -> localhost | SHA256:A0aGCs3/OrkWqitWpkb5E8gAdsAhvcVl1/byB/ZTqzk zuul-build-sshkey
2026-01-09 00:08:40.150057 | controller -> localhost | The key's randomart image is:
2026-01-09 00:08:40.150086 | controller -> localhost | +---[RSA 2048]----+
2026-01-09 00:08:40.150112 | controller -> localhost | |o*o. o= ..       |
2026-01-09 00:08:40.150138 | controller -> localhost | |+o+.++ .  o      |
2026-01-09 00:08:40.150164 | controller -> localhost | |o..=  o  . .     |
2026-01-09 00:08:40.150190 | controller -> localhost | |. o .. .  . +   .|
2026-01-09 00:08:40.150215 | controller -> localhost | |o o  .  S  + o ..|
2026-01-09 00:08:40.150252 | controller -> localhost | | = +. .  .  . +. |
2026-01-09 00:08:40.150281 | controller -> localhost | |. =..+       .o. |
2026-01-09 00:08:40.150306 | controller -> localhost | |.+.o=        E   |
2026-01-09 00:08:40.150330 | controller -> localhost | |*o .oo        .  |
2026-01-09 00:08:40.150355 | controller -> localhost | +----[SHA256]-----+
2026-01-09 00:08:40.150410 | controller -> localhost | ok: Runtime: 0:00:00.291125
2026-01-09 00:08:40.160200 | 
2026-01-09 00:08:40.160287 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-09 00:08:40.193611 | controller | ok
2026-01-09 00:08:40.207090 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-09 00:08:40.217780 | 
2026-01-09 00:08:40.217889 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-09 00:08:40.252646 | controller | skipping: Conditional result was False
2026-01-09 00:08:40.261796 | 
2026-01-09 00:08:40.261937 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-09 00:08:40.722279 | controller | changed
2026-01-09 00:08:40.727915 | 
2026-01-09 00:08:40.727997 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-09 00:08:40.955748 | controller | ok
2026-01-09 00:08:40.964754 | 
2026-01-09 00:08:40.964859 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-09 00:08:41.661904 | controller | changed
2026-01-09 00:08:41.678923 | 
2026-01-09 00:08:41.679121 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-09 00:08:42.325049 | controller | changed
2026-01-09 00:08:42.333596 | 
2026-01-09 00:08:42.333691 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-09 00:08:42.358907 | controller | skipping: Conditional result was False
2026-01-09 00:08:42.368542 | 
2026-01-09 00:08:42.368651 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-09 00:08:42.961569 | controller -> localhost | changed
2026-01-09 00:08:42.975568 | 
2026-01-09 00:08:42.975656 | TASK [add-build-sshkey : Add back temp key]
2026-01-09 00:08:43.276380 | controller -> localhost | Identity added: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_rsa (zuul-build-sshkey)
2026-01-09 00:08:43.276578 | controller -> localhost | ok: Runtime: 0:00:00.015632
2026-01-09 00:08:43.287882 | 
2026-01-09 00:08:43.288099 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-09 00:08:43.673332 | controller | ok
2026-01-09 00:08:43.685652 | 
2026-01-09 00:08:43.685753 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-09 00:08:43.722668 | controller | skipping: Conditional result was False
2026-01-09 00:08:43.740284 | 
2026-01-09 00:08:43.740415 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-09 00:08:43.772193 | controller | ok
2026-01-09 00:08:43.790630 | 
2026-01-09 00:08:43.790762 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-09 00:08:44.091268 | controller -> localhost | ok
2026-01-09 00:08:44.097798 | 
2026-01-09 00:08:44.097862 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-09 00:08:44.129070 | controller | ok
2026-01-09 00:08:44.140711 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-09 00:08:44.147524 | 
2026-01-09 00:08:44.147593 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-09 00:08:44.532360 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-09 00:08:44.532636 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_ecdsa.
2026-01-09 00:08:44.532686 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_ecdsa.pub.
2026-01-09 00:08:44.532726 | controller -> localhost | The key fingerprint is:
2026-01-09 00:08:44.532755 | controller -> localhost | SHA256:DZxYwmnqEqUAplXrjXXwRxSBGIwH1xHB0BJqt9SjaRQ zuul-build-sshkey
2026-01-09 00:08:44.532784 | controller -> localhost | The key's randomart image is:
2026-01-09 00:08:44.532811 | controller -> localhost | +---[ECDSA 521]---+
2026-01-09 00:08:44.532836 | controller -> localhost | |o...o=EX=*=o     |
2026-01-09 00:08:44.532861 | controller -> localhost | |+.  o+OX=o       |
2026-01-09 00:08:44.532885 | controller -> localhost | |.. o++*.O .      |
2026-01-09 00:08:44.532909 | controller -> localhost | |  oo.B = =       |
2026-01-09 00:08:44.532933 | controller -> localhost | |   oo * S .      |
2026-01-09 00:08:44.532957 | controller -> localhost | |  . ..           |
2026-01-09 00:08:44.532980 | controller -> localhost | |   .             |
2026-01-09 00:08:44.533004 | controller -> localhost | |                 |
2026-01-09 00:08:44.533085 | controller -> localhost | |                 |
2026-01-09 00:08:44.533113 | controller -> localhost | +----[SHA256]-----+
2026-01-09 00:08:44.533180 | controller -> localhost | ok: Runtime: 0:00:00.009235
2026-01-09 00:08:44.543982 | 
2026-01-09 00:08:44.544154 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-09 00:08:44.576261 | controller | ok
2026-01-09 00:08:44.585644 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-09 00:08:44.594959 | 
2026-01-09 00:08:44.595057 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-09 00:08:44.620233 | controller | skipping: Conditional result was False
2026-01-09 00:08:44.626933 | 
2026-01-09 00:08:44.627009 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-09 00:08:44.932528 | controller | changed
2026-01-09 00:08:44.938410 | 
2026-01-09 00:08:44.938475 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-09 00:08:45.177861 | controller | ok
2026-01-09 00:08:45.196399 | 
2026-01-09 00:08:45.196594 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-09 00:08:45.856259 | controller | changed
2026-01-09 00:08:45.872707 | 
2026-01-09 00:08:45.872944 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-09 00:08:46.508008 | controller | changed
2026-01-09 00:08:46.561033 | 
2026-01-09 00:08:46.561154 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-09 00:08:46.586567 | controller | skipping: Conditional result was False
2026-01-09 00:08:46.603508 | 
2026-01-09 00:08:46.603678 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-09 00:08:46.869699 | controller -> localhost | changed
2026-01-09 00:08:46.887821 | 
2026-01-09 00:08:46.887974 | TASK [add-build-sshkey : Add back temp key]
2026-01-09 00:08:47.180839 | controller -> localhost | Identity added: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/b78412301bb74216a5668f9ef71b2b31_id_ecdsa (zuul-build-sshkey)
2026-01-09 00:08:47.181113 | controller -> localhost | ok: Runtime: 0:00:00.008094
2026-01-09 00:08:47.187912 | 
2026-01-09 00:08:47.187976 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-09 00:08:47.402890 | controller | ok
2026-01-09 00:08:47.409895 | 
2026-01-09 00:08:47.409979 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-09 00:08:47.444619 | controller | skipping: Conditional result was False
2026-01-09 00:08:47.457091 | 
2026-01-09 00:08:47.457207 | TASK [include_role : remove-zuul-sshkey]
2026-01-09 00:08:47.481154 | controller | skipping: Conditional result was False
2026-01-09 00:08:47.487918 | 
2026-01-09 00:08:47.488002 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-09 00:08:47.738186 | controller | ok: "logs"
2026-01-09 00:08:47.738790 | controller | ok: All items complete
2026-01-09 00:08:47.738853 | 
2026-01-09 00:08:47.931708 | controller | ok: "artifacts"
2026-01-09 00:08:48.133769 | controller | ok: "docs"
2026-01-09 00:08:48.148603 | 
2026-01-09 00:08:48.148755 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-09 00:08:48.393367 | controller | changed: "logs"
2026-01-09 00:08:48.616114 | controller | changed: "artifacts"
2026-01-09 00:08:48.807008 | controller | changed: "docs"
2026-01-09 00:08:48.860966 | 
2026-01-09 00:08:48.861102 | PLAY RECAP
2026-01-09 00:08:48.861148 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-09 00:08:48.861177 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-09 00:08:48.861202 | 
2026-01-09 00:08:49.013155 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-09 00:08:49.014005 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-09 00:08:49.605898 | 
2026-01-09 00:08:49.606077 | PLAY [all]
2026-01-09 00:08:49.631112 | 
2026-01-09 00:08:49.631264 | TASK [Install binary dependencies]
2026-01-09 00:08:49.685505 | controller | ok
2026-01-09 00:08:49.708322 | 
2026-01-09 00:08:49.708463 | TASK [bindep : Include find tasks]
2026-01-09 00:08:49.751300 | controller | ok
2026-01-09 00:08:49.759118 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-09 00:08:49.765665 | 
2026-01-09 00:08:49.765735 | TASK [bindep : Look for bindep.txt]
2026-01-09 00:08:50.131069 | controller | ok
2026-01-09 00:08:50.147459 | 
2026-01-09 00:08:50.147662 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:08:50.175357 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.184513 | 
2026-01-09 00:08:50.184625 | TASK [bindep : Look for other-requirements.txt]
2026-01-09 00:08:50.389367 | controller | ok
2026-01-09 00:08:50.396130 | 
2026-01-09 00:08:50.396238 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:08:50.421686 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.430054 | 
2026-01-09 00:08:50.430193 | TASK [bindep : Look for bindep fallback file]
2026-01-09 00:08:50.457241 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.472656 | 
2026-01-09 00:08:50.473111 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:08:50.503633 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.514370 | 
2026-01-09 00:08:50.514507 | TASK [bindep : Include bindep tasks]
2026-01-09 00:08:50.541241 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.549649 | 
2026-01-09 00:08:50.549841 | TASK [bindep : Include install tasks]
2026-01-09 00:08:50.576774 | controller | skipping: Conditional result was False
2026-01-09 00:08:50.586166 | 
2026-01-09 00:08:50.586313 | LOOP [bindep : Include package tasks]
2026-01-09 00:08:50.648217 | 
2026-01-09 00:08:50.648421 | TASK [Run test-setup role]
2026-01-09 00:08:50.679155 | controller | ok
2026-01-09 00:08:50.702906 | 
2026-01-09 00:08:50.703127 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-09 00:08:50.918758 | controller | ok
2026-01-09 00:08:50.925323 | 
2026-01-09 00:08:50.925385 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-09 00:08:51.459869 | controller | skipping: Conditional result was False
2026-01-09 00:08:51.501583 | 
2026-01-09 00:08:51.501692 | PLAY RECAP
2026-01-09 00:08:51.501736 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-09 00:08:51.501760 | 
2026-01-09 00:08:51.616742 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-09 00:08:51.617778 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-09 00:08:52.276842 | 
2026-01-09 00:08:52.276962 | PLAY [controller]
2026-01-09 00:08:52.297331 | 
2026-01-09 00:08:52.297424 | TASK [Create the /root directory]
2026-01-09 00:08:52.683300 | controller | ok
2026-01-09 00:08:52.689458 | 
2026-01-09 00:08:52.689534 | TASK [Install glibc-langpack-en]
2026-01-09 00:08:56.673480 | controller | ok: Nothing to do
2026-01-09 00:08:56.696363 | 
2026-01-09 00:08:56.696632 | TASK [Ensure controller directory exists]
2026-01-09 00:08:56.909448 | controller | changed
2026-01-09 00:08:56.919090 | 
2026-01-09 00:08:56.919181 | TASK [Install container runtime]
2026-01-09 00:08:56.976869 | controller | ok
2026-01-09 00:08:57.013305 | 
2026-01-09 00:08:57.013443 | LOOP [ensure-podman : Find distribution installation]
2026-01-09 00:08:57.038632 | controller | ok: "/var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-09 00:08:57.055697 | controller | included: /var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-09 00:08:57.062629 | 
2026-01-09 00:08:57.062743 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-09 00:10:02.358948 | controller | changed
2026-01-09 00:10:02.368394 | 
2026-01-09 00:10:02.368495 | TASK [ensure-podman : Fetch podman version]
2026-01-09 00:10:02.905801 | controller | Client:       Podman Engine
2026-01-09 00:10:02.905927 | controller | Version:      4.6.2
2026-01-09 00:10:02.905973 | controller | API Version:  4.6.2
2026-01-09 00:10:02.906014 | controller | Go Version:   go1.19.12
2026-01-09 00:10:02.906065 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-09 00:10:02.906114 | controller | OS/Arch:      linux/amd64
2026-01-09 00:10:03.404815 | controller | ok: Runtime: 0:00:00.201111
2026-01-09 00:10:03.412459 | 
2026-01-09 00:10:03.412580 | TASK [ensure-podman : Print podman version installed]
2026-01-09 00:10:03.443358 | Podman version: Client:       Podman Engine
2026-01-09 00:10:03.443639 | Version:      4.6.2
2026-01-09 00:10:03.443673 | API Version:  4.6.2
2026-01-09 00:10:03.443695 | Go Version:   go1.19.12
2026-01-09 00:10:03.443714 | Built:        Mon Aug 28 19:38:31 2023
2026-01-09 00:10:03.443733 | OS/Arch:      linux/amd64
2026-01-09 00:10:03.450502 | 
2026-01-09 00:10:03.450622 | TASK [ensure-podman : Validate podman engine]
2026-01-09 00:10:03.982710 | controller | skipping: Conditional result was False
2026-01-09 00:10:03.991863 | 
2026-01-09 00:10:03.992052 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-09 00:10:04.006998 | controller | skipping: Conditional result was False
2026-01-09 00:10:04.023806 | 
2026-01-09 00:10:04.024029 | TASK [Ensure python3.8 is present]
2026-01-09 00:10:04.039001 | controller | skipping: Conditional result was False
2026-01-09 00:10:04.048126 | 
2026-01-09 00:10:04.048257 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-09 00:10:04.070710 | controller | ok
2026-01-09 00:10:04.099457 | 
2026-01-09 00:10:04.099630 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-09 00:10:05.678728 | controller | ok: Nothing to do
2026-01-09 00:10:05.693382 | 
2026-01-09 00:10:05.693564 | TASK [our-ensure-python : Also install python3-devel]
2026-01-09 00:10:14.495623 | controller | changed
2026-01-09 00:10:14.507582 | 
2026-01-09 00:10:14.507713 | TASK [Run ensure-virtualenv role]
2026-01-09 00:10:14.528900 | controller | ok
2026-01-09 00:10:14.579354 | 
2026-01-09 00:10:14.579478 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-09 00:10:14.810520 | controller | /usr/bin/virtualenv
2026-01-09 00:10:15.113959 | controller | ok: Runtime: 0:00:00.005560
2026-01-09 00:10:15.121393 | 
2026-01-09 00:10:15.121821 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-09 00:10:15.156708 | controller | skipping: Conditional result was False
2026-01-09 00:10:15.157130 | controller | ok: All items complete
2026-01-09 00:10:15.157173 | 
2026-01-09 00:10:15.178861 | 
2026-01-09 00:10:15.178987 | TASK [Find the full path of the Python interpreter]
2026-01-09 00:10:15.391172 | controller | /usr/bin/python3
2026-01-09 00:10:15.712436 | controller | ok
2026-01-09 00:10:15.726872 | 
2026-01-09 00:10:15.727149 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-09 00:10:16.725783 | controller | created virtual environment CPython3.11.0.final.0-64 in 483ms
2026-01-09 00:10:16.753099 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-09 00:10:16.753115 | 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/.local/share/virtualenv)
2026-01-09 00:10:16.753131 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-09 00:10:16.753144 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-09 00:10:16.786782 | controller | changed
2026-01-09 00:10:16.796151 | 
2026-01-09 00:10:16.796275 | TASK [Set selinux package]
2026-01-09 00:10:16.824806 | controller | ok
2026-01-09 00:10:16.834828 | 
2026-01-09 00:10:16.834953 | TASK [Set selinux package (Fedora)]
2026-01-09 00:10:16.879494 | controller | ok
2026-01-09 00:10:16.886975 | 
2026-01-09 00:10:16.887114 | TASK [Install selinux into virtualenv]
2026-01-09 00:10:42.370825 | controller | Collecting selinux-please-lie-to-me
2026-01-09 00:10:54.637990 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-09 00:10:54.956557 | controller | Collecting setuptools<50.0.0
2026-01-09 00:10:54.962514 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-09 00:10:55.037534 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.3 MB/s eta 0:00:00
2026-01-09 00:10:55.121574 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-09 00:10:55.121808 | controller |   Attempting uninstall: setuptools
2026-01-09 00:10:55.124318 | controller |     Found existing installation: setuptools 62.6.0
2026-01-09 00:10:55.187898 | controller |     Uninstalling setuptools-62.6.0:
2026-01-09 00:10:55.196622 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-09 00:10:55.544039 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-09 00:11:07.007177 | controller |
2026-01-09 00:11:07.089738 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-09 00:11:07.089778 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-09 00:11:07.467903 | controller | ok: Runtime: 0:00:49.969607
2026-01-09 00:11:07.482224 | 
2026-01-09 00:11:07.482386 | TASK [Install pytest-forked into virtualenv]
2026-01-09 00:11:20.403396 | controller | Collecting pytest-forked
2026-01-09 00:11:29.581333 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-09 00:11:29.633695 | controller | Collecting py
2026-01-09 00:11:29.636947 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-09 00:11:29.658052 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.0 MB/s eta 0:00:00
2026-01-09 00:11:29.840427 | controller | Collecting pytest>=3.10
2026-01-09 00:11:29.844133 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-09 00:11:29.858739 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 32.4 MB/s eta 0:00:00
2026-01-09 00:11:29.895902 | controller | Collecting iniconfig>=1.0.1
2026-01-09 00:11:29.899096 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-09 00:11:29.950782 | controller | Collecting packaging>=22
2026-01-09 00:11:29.955038 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2026-01-09 00:11:29.963536 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.9 MB/s eta 0:00:00
2026-01-09 00:11:30.001728 | controller | Collecting pluggy<2,>=1.5
2026-01-09 00:11:30.005112 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-09 00:11:30.057992 | controller | Collecting pygments>=2.7.2
2026-01-09 00:11:30.062571 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-09 00:11:30.117581 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 23.1 MB/s eta 0:00:00
2026-01-09 00:11:30.185053 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-09 00:11:31.237816 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2026-01-09 00:11:31.252107 | controller |
2026-01-09 00:11:31.327498 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-09 00:11:31.327555 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-09 00:11:31.585372 | controller | ok: Runtime: 0:00:23.583142
2026-01-09 00:11:31.595341 | 
2026-01-09 00:11:31.595502 | TASK [Update pip]
2026-01-09 00:11:32.144228 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-09 00:11:44.584050 | controller | Collecting pip
2026-01-09 00:11:56.904828 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-09 00:11:56.985394 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 23.6 MB/s eta 0:00:00
2026-01-09 00:11:57.050747 | controller | Installing collected packages: pip
2026-01-09 00:11:57.050900 | controller |   Attempting uninstall: pip
2026-01-09 00:11:57.053091 | controller |     Found existing installation: pip 22.2.2
2026-01-09 00:11:57.188670 | controller |     Uninstalling pip-22.2.2:
2026-01-09 00:11:57.203346 | controller |       Successfully uninstalled pip-22.2.2
2026-01-09 00:11:57.984017 | controller | Successfully installed pip-25.3
2026-01-09 00:11:58.154786 | controller | ok: Runtime: 0:00:26.224127
2026-01-09 00:11:58.168241 | 
2026-01-09 00:11:58.168435 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-09 00:11:58.397995 | controller | changed
2026-01-09 00:11:58.403883 | 
2026-01-09 00:11:58.403964 | TASK [Install ansible into virtualenv]
2026-01-09 00:11:58.881245 | controller | Processing ./src/github.com/ansible/ansible
2026-01-09 00:11:58.884499 | controller |   Installing build dependencies: started
2026-01-09 00:12:21.801897 | controller |   Installing build dependencies: finished with status 'done'
2026-01-09 00:12:21.803065 | controller |   Getting requirements to build wheel: started
2026-01-09 00:12:22.555276 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-09 00:12:22.556123 | controller |   Preparing metadata (pyproject.toml): started
2026-01-09 00:12:23.027525 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-09 00:12:23.030093 | 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.
2026-01-09 00:12:23.032567 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-09 00:12:23.453266 | controller | ERROR
2026-01-09 00:12:23.453530 | controller | {
2026-01-09 00:12:23.453573 | controller |   "delta": "0:00:24.485989",
2026-01-09 00:12:23.453600 | controller |   "end": "2026-01-09 00:12:23.090828",
2026-01-09 00:12:23.453624 | controller |   "msg": "non-zero return code",
2026-01-09 00:12:23.453684 | controller |   "rc": 1,
2026-01-09 00:12:23.453711 | controller |   "start": "2026-01-09 00:11:58.604839"
2026-01-09 00:12:23.453735 | controller | }
failure
2026-01-09 00:12:23.455764 | 
2026-01-09 00:12:23.455838 | PLAY RECAP
2026-01-09 00:12:23.455904 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-09 00:12:23.455967 | 
2026-01-09 00:12:23.575623 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-09 00:12:23.576652 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-09 00:12:24.174316 | 
2026-01-09 00:12:24.174456 | PLAY [all]
2026-01-09 00:12:24.198117 | 
2026-01-09 00:12:24.198241 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-09 00:12:24.442688 | controller | changed: non-zero return code
2026-01-09 00:12:24.448391 | 
2026-01-09 00:12:24.448470 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-09 00:12:24.461886 | controller | skipping: Conditional result was False
2026-01-09 00:12:24.467713 | 
2026-01-09 00:12:24.467783 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-09 00:12:24.491892 | 
2026-01-09 00:12:24.492107 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-09 00:12:24.518766 | 
2026-01-09 00:12:24.518974 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-09 00:12:24.535311 | controller | skipping: Conditional result was False
2026-01-09 00:12:24.548284 | 
2026-01-09 00:12:24.548604 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-09 00:12:24.575199 | 
2026-01-09 00:12:24.575990 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-09 00:12:24.592995 | controller | skipping: Conditional result was False
2026-01-09 00:12:24.601197 | 
2026-01-09 00:12:24.601312 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-09 00:12:24.615515 | controller | skipping: Conditional result was False
2026-01-09 00:12:24.627076 | 
2026-01-09 00:12:24.627836 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-09 00:12:24.644088 | controller | skipping: Conditional result was False
2026-01-09 00:12:24.681159 | 
2026-01-09 00:12:24.681280 | PLAY RECAP
2026-01-09 00:12:24.681342 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-09 00:12:24.681375 | 
2026-01-09 00:12:24.800419 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-09 00:12:24.801475 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-09 00:12:25.437084 | 
2026-01-09 00:12:25.437255 | PLAY [all:!appliance*]
2026-01-09 00:12:25.469831 | 
2026-01-09 00:12:25.469966 | TASK [unregister the node]
2026-01-09 00:12:26.004986 | controller | skipping: Conditional result was False
2026-01-09 00:12:26.019512 | 
2026-01-09 00:12:26.019906 | TASK [include_role : fetch-output]
2026-01-09 00:12:26.098248 | controller | ok
2026-01-09 00:12:26.120267 | 
2026-01-09 00:12:26.120366 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-09 00:12:26.175175 | controller | skipping: Conditional result was False
2026-01-09 00:12:26.181630 | 
2026-01-09 00:12:26.181738 | TASK [fetch-output : Set log path for single node]
2026-01-09 00:12:26.211994 | controller | ok
2026-01-09 00:12:26.219919 | 
2026-01-09 00:12:26.220057 | LOOP [fetch-output : Ensure local output dirs]
2026-01-09 00:12:26.712032 | controller -> localhost | ok: "/var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/logs"
2026-01-09 00:12:26.947458 | controller -> localhost | changed: "/var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/artifacts"
2026-01-09 00:12:27.176280 | controller -> localhost | changed: "/var/lib/zuul/builds/b78412301bb74216a5668f9ef71b2b31/work/docs"
2026-01-09 00:12:27.197805 | 
2026-01-09 00:12:27.197948 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-09 00:12:27.828676 | controller | changed:
2026-01-09 00:12:27.828866 | controller | .d..t...... ./
2026-01-09 00:12:27.828896 | controller | cd+++++++++ controller/
2026-01-09 00:12:27.828933 | controller | changed: All items complete
2026-01-09 00:12:27.828954 | 
2026-01-09 00:12:28.279005 | controller | changed: .d..t...... ./
2026-01-09 00:12:28.765883 | controller | changed: .d..t...... ./
2026-01-09 00:12:28.796666 | 
2026-01-09 00:12:28.796894 | TASK [include_role : fetch-output-openshift]
2026-01-09 00:12:28.815055 | controller | skipping: Conditional result was False
2026-01-09 00:12:28.831300 | 
2026-01-09 00:12:28.831443 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-09 00:12:28.876598 | controller | skipping: Conditional result was False
2026-01-09 00:12:28.887166 | controller | skipping: Conditional result was False
2026-01-09 00:12:28.948300 | 
2026-01-09 00:12:28.948434 | PLAY [localhost]
2026-01-09 00:12:28.967548 | 
2026-01-09 00:12:28.967683 | TASK [Run Zuul manifest role]
2026-01-09 00:12:28.988129 | localhost | ok
2026-01-09 00:12:29.008212 | 
2026-01-09 00:12:29.008314 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-09 00:12:29.440190 | localhost | changed
2026-01-09 00:12:29.448298 | 
2026-01-09 00:12:29.448411 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-09 00:12:29.490534 | localhost | ok
2026-01-09 00:12:29.502810 | 
2026-01-09 00:12:29.502921 | TASK [Set zuul-log-path fact]
2026-01-09 00:12:29.526003 | localhost | ok
2026-01-09 00:12:29.546952 | 
2026-01-09 00:12:29.547094 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-09 00:12:29.577799 | localhost | ok
2026-01-09 00:12:29.586110 | 
2026-01-09 00:12:29.586214 | LOOP [Run upload-logs-swift role]
2026-01-09 00:12:29.620325 | localhost | Output suppressed because no_log was given
2026-01-09 00:12:29.648848 | 
2026-01-09 00:12:29.648948 | TASK [Set zuul-log-path fact]
2026-01-09 00:12:29.673112 | localhost | skipping: Conditional result was False
2026-01-09 00:12:29.678172 | 
2026-01-09 00:12:29.678236 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-09 00:12:30.134303 | localhost -> localhost | ok: Runtime: 0:00:00.008633
2026-01-09 00:12:30.147785 | 
2026-01-09 00:12:30.147954 | TASK [upload-logs-swift : Upload logs to swift]