2025-12-25 00:22:52.098329 | Job console starting...
2025-12-25 00:22:52.110576 | Updating repositories
2025-12-25 00:22:52.259895 | Preparing job workspace
2025-12-25 00:22:56.382122 | Running Ansible setup...
2025-12-25 00:23:01.353952 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-25 00:23:01.991439 | 
2025-12-25 00:23:01.991571 | PLAY [localhost]
2025-12-25 00:23:02.000698 | 
2025-12-25 00:23:02.000807 | TASK [Gathering Facts]
2025-12-25 00:23:03.029731 | localhost | ok
2025-12-25 00:23:03.063336 | 
2025-12-25 00:23:03.063588 | TASK [Setup log path fact]
2025-12-25 00:23:03.088552 | localhost | ok
2025-12-25 00:23:03.108867 | 
2025-12-25 00:23:03.109084 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-25 00:23:03.151138 | localhost | ok
2025-12-25 00:23:03.161478 | 
2025-12-25 00:23:03.161606 | TASK [emit-job-header : Print job information]
2025-12-25 00:23:03.212535 | # Job Information
2025-12-25 00:23:03.212711 | Ansible Version: 2.15.12
2025-12-25 00:23:03.212743 | Job: ansible-test-sanity-docker-devel
2025-12-25 00:23:03.212765 | Pipeline: periodic
2025-12-25 00:23:03.212783 | Executor: ze01.softwarefactory-project.io
2025-12-25 00:23:03.212802 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-12-25 00:23:03.212823 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/206/ansible/206aac8e30d244c5979b09880c138831/
2025-12-25 00:23:03.212842 | Event ID: 9bcd164eed0a4284892079c0f800abca
2025-12-25 00:23:03.217238 | 
2025-12-25 00:23:03.217327 | LOOP [emit-job-header : Print node information]
2025-12-25 00:23:03.342678 | localhost | ok:
2025-12-25 00:23:03.342906 | localhost | # Node Information
2025-12-25 00:23:03.342939 | localhost | Inventory Hostname: controller
2025-12-25 00:23:03.342964 | localhost | Hostname: np0005570317
2025-12-25 00:23:03.342988 | localhost | Username: zuul
2025-12-25 00:23:03.343032 | localhost | Distro: Fedora 37
2025-12-25 00:23:03.343066 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-12-25 00:23:03.343093 | localhost | Region: ca-ymq-1
2025-12-25 00:23:03.343116 | localhost | Label: ansible-fedora-37-1vcpu
2025-12-25 00:23:03.343138 | localhost | Product Name: OpenStack Nova
2025-12-25 00:23:03.343160 | localhost | Interface IP: 162.253.55.227
2025-12-25 00:23:03.356708 | 
2025-12-25 00:23:03.356871 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-25 00:23:03.802527 | localhost -> localhost | changed
2025-12-25 00:23:03.810323 | 
2025-12-25 00:23:03.810447 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-25 00:23:04.682776 | localhost -> localhost | changed
2025-12-25 00:23:04.703506 | 
2025-12-25 00:23:04.703588 | PLAY [all:!appliance*]
2025-12-25 00:23:04.719844 | 
2025-12-25 00:23:04.719944 | TASK [include_role : start-zuul-console]
2025-12-25 00:23:04.739089 | controller | ok
2025-12-25 00:23:04.753137 | 
2025-12-25 00:23:04.753259 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-25 00:23:05.137845 | controller | ok
2025-12-25 00:23:05.155135 | 
2025-12-25 00:23:05.155283 | TASK [use-our-mirror : Retrieve the IP address]
2025-12-25 00:23:06.081307 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-12-25 00:23:06.091339 | 
2025-12-25 00:23:06.091470 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-12-25 00:23:06.639755 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.651267 | 
2025-12-25 00:23:06.651415 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-12-25 00:23:06.676074 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.694572 | 
2025-12-25 00:23:06.694682 | TASK [use-our-mirror : Create the podman configuration directory]
2025-12-25 00:23:06.718674 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.725685 | 
2025-12-25 00:23:06.725786 | TASK [use-our-mirror : Copy the podman configuration]
2025-12-25 00:23:06.750237 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.756874 | 
2025-12-25 00:23:06.756953 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-12-25 00:23:06.782290 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.789607 | 
2025-12-25 00:23:06.789755 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-12-25 00:23:06.814738 | controller | skipping: Conditional result was False
2025-12-25 00:23:06.846550 | 
2025-12-25 00:23:06.846875 | TASK [Disable Fedora Modular]
2025-12-25 00:23:07.091910 | controller | changed
2025-12-25 00:23:07.100283 | 
2025-12-25 00:23:07.100405 | TASK [Enable EPEL]
2025-12-25 00:23:07.125876 | controller | skipping: Conditional result was False
2025-12-25 00:23:07.135189 | 
2025-12-25 00:23:07.135299 | TASK [Register the RHEL node]
2025-12-25 00:23:07.686399 | 
2025-12-25 00:23:07.686675 | TASK [Show the subscription-manager status]
2025-12-25 00:23:08.273048 | controller | skipping: Conditional result was False
2025-12-25 00:23:08.283698 | 
2025-12-25 00:23:08.283825 | TASK [Enable EPEL on RHEL]
2025-12-25 00:23:08.841576 | controller | skipping: Conditional result was False
2025-12-25 00:23:08.856263 | 
2025-12-25 00:23:08.856422 | TASK [Install git and tox]
2025-12-25 00:24:35.977094 | controller | changed
2025-12-25 00:24:35.983286 | 
2025-12-25 00:24:35.983360 | TASK [include_role : prepare-workspace]
2025-12-25 00:24:36.002558 | controller | ok
2025-12-25 00:24:36.023882 | 
2025-12-25 00:24:36.023998 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-25 00:24:36.238867 | controller | ok
2025-12-25 00:24:36.245668 | 
2025-12-25 00:24:36.245752 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-25 00:24:48.542612 | controller | Output suppressed because no_log was given
2025-12-25 00:24:48.593984 | 
2025-12-25 00:24:48.594149 | TASK [include_role : prepare-workspace-openshift]
2025-12-25 00:24:48.619507 | controller | skipping: Conditional result was False
2025-12-25 00:24:48.642480 | 
2025-12-25 00:24:48.642560 | PLAY [all:!appliance]
2025-12-25 00:24:48.659169 | 
2025-12-25 00:24:48.659244 | TASK [Run add-build-sshkey role (RSA)]
2025-12-25 00:24:48.689510 | controller | ok
2025-12-25 00:24:48.704647 | 
2025-12-25 00:24:48.704733 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-25 00:24:48.983309 | controller -> localhost | ok
2025-12-25 00:24:48.991070 | 
2025-12-25 00:24:48.991166 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-25 00:24:49.012607 | controller | ok
2025-12-25 00:24:49.029061 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-25 00:24:49.035479 | 
2025-12-25 00:24:49.035588 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-25 00:24:49.629235 | controller -> localhost | Generating public/private rsa key pair.
2025-12-25 00:24:49.629457 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_rsa.
2025-12-25 00:24:49.629486 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_rsa.pub.
2025-12-25 00:24:49.629507 | controller -> localhost | The key fingerprint is:
2025-12-25 00:24:49.629526 | controller -> localhost | SHA256:z0N+kCwU7nUzyQGXln4Jc+n1D0FROzfDxsJtUlCHmII zuul-build-sshkey
2025-12-25 00:24:49.629544 | controller -> localhost | The key's randomart image is:
2025-12-25 00:24:49.629562 | controller -> localhost | +---[RSA 2048]----+
2025-12-25 00:24:49.629580 | controller -> localhost | |        ....oB=Bo|
2025-12-25 00:24:49.629598 | controller -> localhost | |       .E..oXoX +|
2025-12-25 00:24:49.629616 | controller -> localhost | |        o .+*O #o|
2025-12-25 00:24:49.629632 | controller -> localhost | |       o o o.oX *|
2025-12-25 00:24:49.629649 | controller -> localhost | |        S =  . ..|
2025-12-25 00:24:49.629676 | controller -> localhost | |         * .    .|
2025-12-25 00:24:49.629697 | controller -> localhost | |          = .    |
2025-12-25 00:24:49.629716 | controller -> localhost | |           o     |
2025-12-25 00:24:49.629734 | controller -> localhost | |                 |
2025-12-25 00:24:49.629754 | controller -> localhost | +----[SHA256]-----+
2025-12-25 00:24:49.629804 | controller -> localhost | ok: Runtime: 0:00:00.183411
2025-12-25 00:24:49.636460 | 
2025-12-25 00:24:49.636522 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-25 00:24:49.668505 | controller | ok
2025-12-25 00:24:49.678557 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-25 00:24:49.687649 | 
2025-12-25 00:24:49.687719 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-25 00:24:49.712806 | controller | skipping: Conditional result was False
2025-12-25 00:24:49.719478 | 
2025-12-25 00:24:49.719549 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-25 00:24:50.182831 | controller | changed
2025-12-25 00:24:50.193634 | 
2025-12-25 00:24:50.193773 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-25 00:24:50.402172 | controller | ok
2025-12-25 00:24:50.410378 | 
2025-12-25 00:24:50.410463 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-25 00:24:51.065106 | controller | changed
2025-12-25 00:24:51.078839 | 
2025-12-25 00:24:51.078994 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-25 00:24:51.693864 | controller | changed
2025-12-25 00:24:51.707899 | 
2025-12-25 00:24:51.708105 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-25 00:24:51.746254 | controller | skipping: Conditional result was False
2025-12-25 00:24:51.760842 | 
2025-12-25 00:24:51.761066 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-25 00:24:52.167433 | controller -> localhost | changed
2025-12-25 00:24:52.186270 | 
2025-12-25 00:24:52.186428 | TASK [add-build-sshkey : Add back temp key]
2025-12-25 00:24:52.490964 | controller -> localhost | Identity added: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_rsa (zuul-build-sshkey)
2025-12-25 00:24:52.491332 | controller -> localhost | ok: Runtime: 0:00:00.013443
2025-12-25 00:24:52.498922 | 
2025-12-25 00:24:52.499036 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-25 00:24:52.908585 | controller | ok
2025-12-25 00:24:52.921563 | 
2025-12-25 00:24:52.921713 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-25 00:24:52.960568 | controller | skipping: Conditional result was False
2025-12-25 00:24:52.987300 | 
2025-12-25 00:24:52.987464 | TASK [Run add-build-sshkey role (ECDSA)]
2025-12-25 00:24:53.015181 | controller | ok
2025-12-25 00:24:53.038248 | 
2025-12-25 00:24:53.038356 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-25 00:24:53.310067 | controller -> localhost | ok
2025-12-25 00:24:53.328287 | 
2025-12-25 00:24:53.328477 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-25 00:24:53.359222 | controller | ok
2025-12-25 00:24:53.378156 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-25 00:24:53.384378 | 
2025-12-25 00:24:53.384442 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-25 00:24:53.673564 | controller -> localhost | Generating public/private ecdsa key pair.
2025-12-25 00:24:53.673804 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_ecdsa.
2025-12-25 00:24:53.673844 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_ecdsa.pub.
2025-12-25 00:24:53.673880 | controller -> localhost | The key fingerprint is:
2025-12-25 00:24:53.673908 | controller -> localhost | SHA256:1Xcu4PaAWaTYh3C4XBEaUwu8OQECn3KQYXJLCXuCMlg zuul-build-sshkey
2025-12-25 00:24:53.673935 | controller -> localhost | The key's randomart image is:
2025-12-25 00:24:53.673963 | controller -> localhost | +---[ECDSA 521]---+
2025-12-25 00:24:53.673988 | controller -> localhost | |o.E=. .o=o=o.    |
2025-12-25 00:24:53.674010 | controller -> localhost | |oBo+ o  +X.*     |
2025-12-25 00:24:53.674085 | controller -> localhost | |B + +  .o** = . .|
2025-12-25 00:24:53.674105 | controller -> localhost | |.+ o    *. * o o |
2025-12-25 00:24:53.674123 | controller -> localhost | |        S.o + . .|
2025-12-25 00:24:53.674140 | controller -> localhost | |           . o . |
2025-12-25 00:24:53.674157 | controller -> localhost | |              .  |
2025-12-25 00:24:53.674174 | controller -> localhost | |                 |
2025-12-25 00:24:53.674191 | controller -> localhost | |                 |
2025-12-25 00:24:53.674208 | controller -> localhost | +----[SHA256]-----+
2025-12-25 00:24:53.674257 | controller -> localhost | ok: Runtime: 0:00:00.008520
2025-12-25 00:24:53.681406 | 
2025-12-25 00:24:53.681468 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-25 00:24:53.711577 | controller | ok
2025-12-25 00:24:53.718934 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-25 00:24:53.728359 | 
2025-12-25 00:24:53.728429 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-25 00:24:53.743488 | controller | skipping: Conditional result was False
2025-12-25 00:24:53.751642 | 
2025-12-25 00:24:53.751709 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-25 00:24:54.022956 | controller | changed
2025-12-25 00:24:54.036793 | 
2025-12-25 00:24:54.036924 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-25 00:24:54.282954 | controller | ok
2025-12-25 00:24:54.296539 | 
2025-12-25 00:24:54.296777 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-25 00:24:54.958241 | controller | changed
2025-12-25 00:24:54.964237 | 
2025-12-25 00:24:54.964313 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-25 00:24:55.567813 | controller | changed
2025-12-25 00:24:55.577245 | 
2025-12-25 00:24:55.577388 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-25 00:24:55.593366 | controller | skipping: Conditional result was False
2025-12-25 00:24:55.601646 | 
2025-12-25 00:24:55.601800 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-25 00:24:55.850893 | controller -> localhost | changed
2025-12-25 00:24:55.913787 | 
2025-12-25 00:24:55.913933 | TASK [add-build-sshkey : Add back temp key]
2025-12-25 00:24:56.236332 | controller -> localhost | Identity added: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/206aac8e30d244c5979b09880c138831_id_ecdsa (zuul-build-sshkey)
2025-12-25 00:24:56.236580 | controller -> localhost | ok: Runtime: 0:00:00.010007
2025-12-25 00:24:56.244198 | 
2025-12-25 00:24:56.244286 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-25 00:24:56.448615 | controller | ok
2025-12-25 00:24:56.455870 | 
2025-12-25 00:24:56.456009 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-25 00:24:56.480544 | controller | skipping: Conditional result was False
2025-12-25 00:24:56.492490 | 
2025-12-25 00:24:56.492566 | TASK [include_role : remove-zuul-sshkey]
2025-12-25 00:24:56.506156 | controller | skipping: Conditional result was False
2025-12-25 00:24:56.513310 | 
2025-12-25 00:24:56.513388 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-25 00:24:56.736344 | controller | ok: "logs"
2025-12-25 00:24:56.736681 | controller | ok: All items complete
2025-12-25 00:24:56.736721 | 
2025-12-25 00:24:56.934571 | controller | ok: "artifacts"
2025-12-25 00:24:57.124849 | controller | ok: "docs"
2025-12-25 00:24:57.141760 | 
2025-12-25 00:24:57.141887 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-25 00:24:57.396597 | controller | changed: "logs"
2025-12-25 00:24:57.590474 | controller | changed: "artifacts"
2025-12-25 00:24:57.785255 | controller | changed: "docs"
2025-12-25 00:24:57.848360 | 
2025-12-25 00:24:57.848483 | PLAY RECAP
2025-12-25 00:24:57.848555 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-12-25 00:24:57.848599 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-25 00:24:57.848624 | 
2025-12-25 00:24:57.979636 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-25 00:24:57.980641 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-25 00:24:58.609186 | 
2025-12-25 00:24:58.609319 | PLAY [all]
2025-12-25 00:24:58.633486 | 
2025-12-25 00:24:58.633619 | TASK [Install binary dependencies]
2025-12-25 00:24:58.684123 | controller | ok
2025-12-25 00:24:58.705181 | 
2025-12-25 00:24:58.705340 | TASK [bindep : Include find tasks]
2025-12-25 00:24:58.735921 | controller | ok
2025-12-25 00:24:58.744816 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-25 00:24:58.751569 | 
2025-12-25 00:24:58.751652 | TASK [bindep : Look for bindep.txt]
2025-12-25 00:24:59.131128 | controller | ok
2025-12-25 00:24:59.147712 | 
2025-12-25 00:24:59.147906 | TASK [bindep : Define bindep_file fact]
2025-12-25 00:24:59.165083 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.180500 | 
2025-12-25 00:24:59.180840 | TASK [bindep : Look for other-requirements.txt]
2025-12-25 00:24:59.391413 | controller | ok
2025-12-25 00:24:59.398136 | 
2025-12-25 00:24:59.398300 | TASK [bindep : Define bindep_file fact]
2025-12-25 00:24:59.437250 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.448125 | 
2025-12-25 00:24:59.448275 | TASK [bindep : Look for bindep fallback file]
2025-12-25 00:24:59.474394 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.484352 | 
2025-12-25 00:24:59.484570 | TASK [bindep : Define bindep_file fact]
2025-12-25 00:24:59.510738 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.520946 | 
2025-12-25 00:24:59.521164 | TASK [bindep : Include bindep tasks]
2025-12-25 00:24:59.547062 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.556630 | 
2025-12-25 00:24:59.556762 | TASK [bindep : Include install tasks]
2025-12-25 00:24:59.582953 | controller | skipping: Conditional result was False
2025-12-25 00:24:59.591172 | 
2025-12-25 00:24:59.591342 | LOOP [bindep : Include package tasks]
2025-12-25 00:24:59.649945 | 
2025-12-25 00:24:59.650273 | TASK [Run test-setup role]
2025-12-25 00:24:59.674314 | controller | ok
2025-12-25 00:24:59.704162 | 
2025-12-25 00:24:59.704437 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-25 00:24:59.909760 | controller | ok
2025-12-25 00:24:59.917197 | 
2025-12-25 00:24:59.917340 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-25 00:25:00.453346 | controller | skipping: Conditional result was False
2025-12-25 00:25:00.481822 | 
2025-12-25 00:25:00.481928 | PLAY RECAP
2025-12-25 00:25:00.481984 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-25 00:25:00.482010 | 
2025-12-25 00:25:00.655273 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-25 00:25:00.656989 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-25 00:25:01.281962 | 
2025-12-25 00:25:01.282126 | PLAY [controller]
2025-12-25 00:25:01.303668 | 
2025-12-25 00:25:01.303824 | TASK [Create the /root directory]
2025-12-25 00:25:01.675785 | controller | ok
2025-12-25 00:25:01.684635 | 
2025-12-25 00:25:01.684790 | TASK [Install glibc-langpack-en]
2025-12-25 00:25:05.659812 | controller | ok: Nothing to do
2025-12-25 00:25:05.665666 | 
2025-12-25 00:25:05.665753 | TASK [Ensure controller directory exists]
2025-12-25 00:25:05.867878 | controller | changed
2025-12-25 00:25:05.875384 | 
2025-12-25 00:25:05.875488 | TASK [Install container runtime]
2025-12-25 00:25:05.947763 | controller | ok
2025-12-25 00:25:05.982854 | 
2025-12-25 00:25:05.982965 | LOOP [ensure-podman : Find distribution installation]
2025-12-25 00:25:06.034709 | controller | ok: "/var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-12-25 00:25:06.047622 | controller | included: /var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-12-25 00:25:06.053940 | 
2025-12-25 00:25:06.054008 | TASK [ensure-podman : Install podman (RedHat)]
2025-12-25 00:26:11.245841 | controller | changed
2025-12-25 00:26:11.260128 | 
2025-12-25 00:26:11.260268 | TASK [ensure-podman : Fetch podman version]
2025-12-25 00:26:11.781778 | controller | Client:       Podman Engine
2025-12-25 00:26:11.781871 | controller | Version:      4.6.2
2025-12-25 00:26:11.781916 | controller | API Version:  4.6.2
2025-12-25 00:26:11.781958 | controller | Go Version:   go1.19.12
2025-12-25 00:26:11.782011 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-12-25 00:26:11.782055 | controller | OS/Arch:      linux/amd64
2025-12-25 00:26:12.309701 | controller | ok: Runtime: 0:00:00.179570
2025-12-25 00:26:12.324911 | 
2025-12-25 00:26:12.325156 | TASK [ensure-podman : Print podman version installed]
2025-12-25 00:26:12.355147 | Podman version: Client:       Podman Engine
2025-12-25 00:26:12.355395 | Version:      4.6.2
2025-12-25 00:26:12.355456 | API Version:  4.6.2
2025-12-25 00:26:12.355501 | Go Version:   go1.19.12
2025-12-25 00:26:12.355541 | Built:        Mon Aug 28 19:38:31 2023
2025-12-25 00:26:12.355581 | OS/Arch:      linux/amd64
2025-12-25 00:26:12.368197 | 
2025-12-25 00:26:12.368332 | TASK [ensure-podman : Validate podman engine]
2025-12-25 00:26:12.913607 | controller | skipping: Conditional result was False
2025-12-25 00:26:12.929544 | 
2025-12-25 00:26:12.929732 | TASK [ensure-podman : Set up docker compatability socket]
2025-12-25 00:26:12.946863 | controller | skipping: Conditional result was False
2025-12-25 00:26:12.973590 | 
2025-12-25 00:26:12.973779 | TASK [Ensure python3.8 is present]
2025-12-25 00:26:12.991170 | controller | skipping: Conditional result was False
2025-12-25 00:26:13.001191 | 
2025-12-25 00:26:13.001379 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-12-25 00:26:13.027470 | controller | ok
2025-12-25 00:26:13.060110 | 
2025-12-25 00:26:13.060257 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-12-25 00:26:14.473565 | controller | ok: Nothing to do
2025-12-25 00:26:14.481717 | 
2025-12-25 00:26:14.481887 | TASK [our-ensure-python : Also install python3-devel]
2025-12-25 00:26:24.084397 | controller | changed
2025-12-25 00:26:24.097381 | 
2025-12-25 00:26:24.097510 | TASK [Run ensure-virtualenv role]
2025-12-25 00:26:24.122201 | controller | ok
2025-12-25 00:26:24.150281 | 
2025-12-25 00:26:24.150442 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-12-25 00:26:24.397576 | controller | /usr/bin/virtualenv
2025-12-25 00:26:24.727196 | controller | ok: Runtime: 0:00:00.004998
2025-12-25 00:26:24.735573 | 
2025-12-25 00:26:24.735664 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-12-25 00:26:24.760597 | controller | skipping: Conditional result was False
2025-12-25 00:26:24.761126 | controller | ok: All items complete
2025-12-25 00:26:24.761189 | 
2025-12-25 00:26:24.807939 | 
2025-12-25 00:26:24.808208 | TASK [Find the full path of the Python interpreter]
2025-12-25 00:26:25.040413 | controller | /usr/bin/python3
2025-12-25 00:26:25.367815 | controller | ok
2025-12-25 00:26:25.377310 | 
2025-12-25 00:26:25.377470 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-12-25 00:26:26.211744 | controller | created virtual environment CPython3.11.0.final.0-64 in 524ms
2025-12-25 00:26:26.234350 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-12-25 00:26:26.234821 | 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)
2025-12-25 00:26:26.234864 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-12-25 00:26:26.234877 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-12-25 00:26:26.429050 | controller | changed
2025-12-25 00:26:26.438931 | 
2025-12-25 00:26:26.439078 | TASK [Set selinux package]
2025-12-25 00:26:26.463847 | controller | ok
2025-12-25 00:26:26.472217 | 
2025-12-25 00:26:26.472333 | TASK [Set selinux package (Fedora)]
2025-12-25 00:26:26.527386 | controller | ok
2025-12-25 00:26:26.535386 | 
2025-12-25 00:26:26.535481 | TASK [Install selinux into virtualenv]
2025-12-25 00:27:03.959626 | controller | Collecting selinux-please-lie-to-me
2025-12-25 00:27:16.223495 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-12-25 00:27:16.532608 | controller | Collecting setuptools<50.0.0
2025-12-25 00:27:16.536862 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-12-25 00:27:16.596294 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 14.7 MB/s eta 0:00:00
2025-12-25 00:27:16.678147 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-12-25 00:27:16.678405 | controller |   Attempting uninstall: setuptools
2025-12-25 00:27:16.680850 | controller |     Found existing installation: setuptools 62.6.0
2025-12-25 00:27:16.741043 | controller |     Uninstalling setuptools-62.6.0:
2025-12-25 00:27:16.749179 | controller |       Successfully uninstalled setuptools-62.6.0
2025-12-25 00:27:17.088764 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-12-25 00:27:32.461987 | controller |
2025-12-25 00:27:32.543633 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-25 00:27:32.543670 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-25 00:27:32.611888 | controller | ok: Runtime: 0:01:05.783296
2025-12-25 00:27:32.620845 | 
2025-12-25 00:27:32.621074 | TASK [Install pytest-forked into virtualenv]
2025-12-25 00:27:57.476418 | controller | Collecting pytest-forked
2025-12-25 00:28:21.652209 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-12-25 00:28:21.706543 | controller | Collecting py
2025-12-25 00:28:21.709658 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-12-25 00:28:21.732763 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.8 MB/s eta 0:00:00
2025-12-25 00:28:21.841906 | controller | Collecting pytest>=3.10
2025-12-25 00:28:21.846126 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2025-12-25 00:28:21.862758 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 26.6 MB/s eta 0:00:00
2025-12-25 00:28:21.900230 | controller | Collecting iniconfig>=1.0.1
2025-12-25 00:28:21.903381 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-12-25 00:28:21.944930 | controller | Collecting packaging>=22
2025-12-25 00:28:21.948093 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-12-25 00:28:21.954749 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 14.3 MB/s eta 0:00:00
2025-12-25 00:28:21.984296 | controller | Collecting pluggy<2,>=1.5
2025-12-25 00:28:21.987414 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-12-25 00:28:22.040698 | controller | Collecting pygments>=2.7.2
2025-12-25 00:28:22.043664 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-12-25 00:28:22.076065 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 46.2 MB/s eta 0:00:00
2025-12-25 00:28:22.145402 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-12-25 00:28:23.196718 | 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
2025-12-25 00:28:23.205326 | controller |
2025-12-25 00:28:23.270114 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-25 00:28:23.270155 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-25 00:28:23.686580 | controller | ok: Runtime: 0:00:50.412043
2025-12-25 00:28:23.693031 | 
2025-12-25 00:28:23.693099 | TASK [Update pip]
2025-12-25 00:28:24.224718 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-12-25 00:28:36.635783 | controller | Collecting pip
2025-12-25 00:28:48.841128 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-12-25 00:28:48.925263 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.6 MB/s eta 0:00:00
2025-12-25 00:28:48.988627 | controller | Installing collected packages: pip
2025-12-25 00:28:48.988762 | controller |   Attempting uninstall: pip
2025-12-25 00:28:48.990973 | controller |     Found existing installation: pip 22.2.2
2025-12-25 00:28:49.128397 | controller |     Uninstalling pip-22.2.2:
2025-12-25 00:28:49.143908 | controller |       Successfully uninstalled pip-22.2.2
2025-12-25 00:28:49.950019 | controller | Successfully installed pip-25.3
2025-12-25 00:28:50.239565 | controller | ok: Runtime: 0:00:26.106209
2025-12-25 00:28:50.246359 | 
2025-12-25 00:28:50.246477 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-12-25 00:28:50.467569 | controller | changed
2025-12-25 00:28:50.481592 | 
2025-12-25 00:28:50.481780 | TASK [Install ansible into virtualenv]
2025-12-25 00:28:51.002747 | controller | Processing ./src/github.com/ansible/ansible
2025-12-25 00:28:51.005970 | controller |   Installing build dependencies: started
2025-12-25 00:29:29.505438 | controller |   Installing build dependencies: finished with status 'done'
2025-12-25 00:29:29.505964 | controller |   Getting requirements to build wheel: started
2025-12-25 00:29:30.234220 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-12-25 00:29:30.235529 | controller |   Preparing metadata (pyproject.toml): started
2025-12-25 00:29:30.698518 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-12-25 00:29:30.703279 | 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-12-25 00:29:30.706847 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-12-25 00:29:31.049492 | controller | ERROR
2025-12-25 00:29:31.049798 | controller | {
2025-12-25 00:29:31.049860 | controller |   "delta": "0:00:40.065495",
2025-12-25 00:29:31.049903 | controller |   "end": "2025-12-25 00:29:30.777646",
2025-12-25 00:29:31.049944 | controller |   "msg": "non-zero return code",
2025-12-25 00:29:31.050004 | controller |   "rc": 1,
2025-12-25 00:29:31.050083 | controller |   "start": "2025-12-25 00:28:50.712151"
2025-12-25 00:29:31.050122 | controller | }
failure
2025-12-25 00:29:31.052726 | 
2025-12-25 00:29:31.052822 | PLAY RECAP
2025-12-25 00:29:31.052903 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-12-25 00:29:31.052949 | 
2025-12-25 00:29:31.182622 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-25 00:29:31.183785 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-25 00:29:31.778953 | 
2025-12-25 00:29:31.779100 | PLAY [all]
2025-12-25 00:29:31.802529 | 
2025-12-25 00:29:31.802680 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-25 00:29:32.056682 | controller | changed: non-zero return code
2025-12-25 00:29:32.070077 | 
2025-12-25 00:29:32.070242 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-25 00:29:32.086135 | controller | skipping: Conditional result was False
2025-12-25 00:29:32.093977 | 
2025-12-25 00:29:32.094109 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-25 00:29:32.118542 | 
2025-12-25 00:29:32.118695 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-25 00:29:32.150824 | 
2025-12-25 00:29:32.151140 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-25 00:29:32.166109 | controller | skipping: Conditional result was False
2025-12-25 00:29:32.177200 | 
2025-12-25 00:29:32.177307 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-25 00:29:32.210107 | 
2025-12-25 00:29:32.210383 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-25 00:29:32.235269 | controller | skipping: Conditional result was False
2025-12-25 00:29:32.244632 | 
2025-12-25 00:29:32.244823 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-25 00:29:32.259805 | controller | skipping: Conditional result was False
2025-12-25 00:29:32.269688 | 
2025-12-25 00:29:32.269797 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-25 00:29:32.305062 | controller | skipping: Conditional result was False
2025-12-25 00:29:32.345793 | 
2025-12-25 00:29:32.345984 | PLAY RECAP
2025-12-25 00:29:32.346088 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-25 00:29:32.346122 | 
2025-12-25 00:29:32.451584 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-25 00:29:32.452504 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-12-25 00:29:33.000605 | 
2025-12-25 00:29:33.000789 | PLAY [all:!appliance*]
2025-12-25 00:29:33.023207 | 
2025-12-25 00:29:33.023308 | TASK [unregister the node]
2025-12-25 00:29:33.555156 | controller | skipping: Conditional result was False
2025-12-25 00:29:33.570313 | 
2025-12-25 00:29:33.570569 | TASK [include_role : fetch-output]
2025-12-25 00:29:33.603981 | controller | ok
2025-12-25 00:29:33.624313 | 
2025-12-25 00:29:33.624431 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-25 00:29:33.669303 | controller | skipping: Conditional result was False
2025-12-25 00:29:33.675816 | 
2025-12-25 00:29:33.675941 | TASK [fetch-output : Set log path for single node]
2025-12-25 00:29:33.710847 | controller | ok
2025-12-25 00:29:33.716294 | 
2025-12-25 00:29:33.716358 | LOOP [fetch-output : Ensure local output dirs]
2025-12-25 00:29:34.103129 | controller -> localhost | ok: "/var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/logs"
2025-12-25 00:29:34.378247 | controller -> localhost | changed: "/var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/artifacts"
2025-12-25 00:29:34.596389 | controller -> localhost | changed: "/var/lib/zuul/builds/206aac8e30d244c5979b09880c138831/work/docs"
2025-12-25 00:29:34.611167 | 
2025-12-25 00:29:34.611307 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-25 00:29:35.316689 | controller | changed:
2025-12-25 00:29:35.317111 | controller | .d..t...... ./
2025-12-25 00:29:35.317196 | controller | cd+++++++++ controller/
2025-12-25 00:29:35.317272 | controller | changed: All items complete
2025-12-25 00:29:35.317322 | 
2025-12-25 00:29:35.808225 | controller | changed: .d..t...... ./
2025-12-25 00:29:36.284420 | controller | changed: .d..t...... ./
2025-12-25 00:29:36.303837 | 
2025-12-25 00:29:36.303975 | TASK [include_role : fetch-output-openshift]
2025-12-25 00:29:36.319583 | controller | skipping: Conditional result was False
2025-12-25 00:29:36.327608 | 
2025-12-25 00:29:36.327704 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-25 00:29:36.352828 | controller | skipping: Conditional result was False
2025-12-25 00:29:36.361598 | controller | skipping: Conditional result was False
2025-12-25 00:29:36.420534 | 
2025-12-25 00:29:36.420684 | PLAY [localhost]
2025-12-25 00:29:36.448003 | 
2025-12-25 00:29:36.448198 | TASK [Run Zuul manifest role]
2025-12-25 00:29:36.471428 | localhost | ok
2025-12-25 00:29:36.491861 | 
2025-12-25 00:29:36.492008 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-25 00:29:36.869210 | localhost | changed
2025-12-25 00:29:36.875489 | 
2025-12-25 00:29:36.875578 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-25 00:29:36.907347 | localhost | ok
2025-12-25 00:29:36.918463 | 
2025-12-25 00:29:36.918550 | TASK [Set zuul-log-path fact]
2025-12-25 00:29:36.939873 | localhost | ok
2025-12-25 00:29:36.958669 | 
2025-12-25 00:29:36.958812 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-25 00:29:36.992372 | localhost | ok
2025-12-25 00:29:37.005837 | 
2025-12-25 00:29:37.005974 | LOOP [Run upload-logs-swift role]
2025-12-25 00:29:37.043748 | localhost | Output suppressed because no_log was given
2025-12-25 00:29:37.078226 | 
2025-12-25 00:29:37.078362 | TASK [Set zuul-log-path fact]
2025-12-25 00:29:37.104445 | localhost | skipping: Conditional result was False
2025-12-25 00:29:37.112611 | 
2025-12-25 00:29:37.112733 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-12-25 00:29:37.550203 | localhost -> localhost | ok: Runtime: 0:00:00.005770
2025-12-25 00:29:37.559112 | 
2025-12-25 00:29:37.559227 | TASK [upload-logs-swift : Upload logs to swift]