2025-09-27 00:17:01.107612 | Job console starting...
2025-09-27 00:17:01.117703 | Updating repositories
2025-09-27 00:17:01.278519 | Preparing job workspace
2025-09-27 00:17:05.286477 | Running Ansible setup...
2025-09-27 00:17:10.147077 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-27 00:17:10.776238 | 
2025-09-27 00:17:10.776422 | PLAY [localhost]
2025-09-27 00:17:10.786247 | 
2025-09-27 00:17:10.786380 | TASK [Gathering Facts]
2025-09-27 00:17:11.745482 | localhost | ok
2025-09-27 00:17:11.767313 | 
2025-09-27 00:17:11.767484 | TASK [Setup log path fact]
2025-09-27 00:17:11.786252 | localhost | ok
2025-09-27 00:17:11.800007 | 
2025-09-27 00:17:11.800149 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-27 00:17:11.829135 | localhost | ok
2025-09-27 00:17:11.838334 | 
2025-09-27 00:17:11.838468 | TASK [emit-job-header : Print job information]
2025-09-27 00:17:11.868297 | # Job Information
2025-09-27 00:17:11.868492 | Ansible Version: 2.15.12
2025-09-27 00:17:11.868712 | Job: ansible-test-sanity-docker-devel
2025-09-27 00:17:11.868746 | Pipeline: periodic
2025-09-27 00:17:11.868772 | Executor: ze04.softwarefactory-project.io
2025-09-27 00:17:11.868796 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-27 00:17:11.868823 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/025/ansible/02501938909d41159dc78ac4f100c340/
2025-09-27 00:17:11.868848 | Event ID: 6059628ede9d40b08c9c7e960ce1822b
2025-09-27 00:17:11.873852 | 
2025-09-27 00:17:11.873959 | LOOP [emit-job-header : Print node information]
2025-09-27 00:17:11.984386 | localhost | ok:
2025-09-27 00:17:11.984846 | localhost | # Node Information
2025-09-27 00:17:11.984876 | localhost | Inventory Hostname: controller
2025-09-27 00:17:11.984896 | localhost | Hostname: np0005456538
2025-09-27 00:17:11.984916 | localhost | Username: zuul
2025-09-27 00:17:11.984940 | localhost | Distro: Fedora 37
2025-09-27 00:17:11.984960 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-09-27 00:17:11.984978 | localhost | Region: ca-ymq-1
2025-09-27 00:17:11.984995 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-27 00:17:11.985012 | localhost | Product Name: OpenStack Nova
2025-09-27 00:17:11.985029 | localhost | Interface IP: 162.253.55.186
2025-09-27 00:17:11.999863 | 
2025-09-27 00:17:11.999982 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-27 00:17:12.513865 | localhost -> localhost | changed
2025-09-27 00:17:12.520005 | 
2025-09-27 00:17:12.520095 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-27 00:17:13.424459 | localhost -> localhost | changed
2025-09-27 00:17:13.450828 | 
2025-09-27 00:17:13.450934 | PLAY [all:!appliance*]
2025-09-27 00:17:13.479466 | 
2025-09-27 00:17:13.479824 | TASK [include_role : start-zuul-console]
2025-09-27 00:17:13.500025 | controller | ok
2025-09-27 00:17:13.516059 | 
2025-09-27 00:17:13.516168 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-27 00:17:13.856021 | controller | ok
2025-09-27 00:17:13.873758 | 
2025-09-27 00:17:13.873894 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-27 00:17:14.646649 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-27 00:17:14.661112 | 
2025-09-27 00:17:14.661287 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-27 00:17:15.217887 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.227017 | 
2025-09-27 00:17:15.227169 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-27 00:17:15.252326 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.261098 | 
2025-09-27 00:17:15.261206 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-27 00:17:15.286159 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.294909 | 
2025-09-27 00:17:15.295001 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-27 00:17:15.320324 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.329161 | 
2025-09-27 00:17:15.329281 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-27 00:17:15.354162 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.363498 | 
2025-09-27 00:17:15.363638 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-27 00:17:15.390607 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.408599 | 
2025-09-27 00:17:15.408765 | TASK [Disable Fedora Modular]
2025-09-27 00:17:15.659350 | controller | changed
2025-09-27 00:17:15.669455 | 
2025-09-27 00:17:15.669617 | TASK [Enable EPEL]
2025-09-27 00:17:15.702183 | controller | skipping: Conditional result was False
2025-09-27 00:17:15.708596 | 
2025-09-27 00:17:15.708725 | TASK [Register the RHEL node]
2025-09-27 00:17:16.257290 | 
2025-09-27 00:17:16.257572 | TASK [Show the subscription-manager status]
2025-09-27 00:17:16.840655 | controller | skipping: Conditional result was False
2025-09-27 00:17:16.855593 | 
2025-09-27 00:17:16.855785 | TASK [Enable EPEL on RHEL]
2025-09-27 00:17:17.416385 | controller | skipping: Conditional result was False
2025-09-27 00:17:17.430247 | 
2025-09-27 00:17:17.430453 | TASK [Install git and tox]
2025-09-27 00:18:51.259859 | controller | changed
2025-09-27 00:18:51.266027 | 
2025-09-27 00:18:51.266090 | TASK [include_role : prepare-workspace]
2025-09-27 00:18:51.297118 | controller | ok
2025-09-27 00:18:51.326158 | 
2025-09-27 00:18:51.326297 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-27 00:18:51.573012 | controller | ok
2025-09-27 00:18:51.583310 | 
2025-09-27 00:18:51.583420 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-27 00:19:04.074657 | controller | Output suppressed because no_log was given
2025-09-27 00:19:04.090983 | 
2025-09-27 00:19:04.091124 | TASK [include_role : prepare-workspace-openshift]
2025-09-27 00:19:04.116697 | controller | skipping: Conditional result was False
2025-09-27 00:19:04.179452 | 
2025-09-27 00:19:04.179548 | PLAY [all:!appliance]
2025-09-27 00:19:04.195923 | 
2025-09-27 00:19:04.196259 | TASK [Run add-build-sshkey role (RSA)]
2025-09-27 00:19:04.217912 | controller | ok
2025-09-27 00:19:04.234522 | 
2025-09-27 00:19:04.234610 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-27 00:19:04.483657 | controller -> localhost | ok
2025-09-27 00:19:04.494034 | 
2025-09-27 00:19:04.494121 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-27 00:19:04.535246 | controller | ok
2025-09-27 00:19:04.558618 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-27 00:19:04.566426 | 
2025-09-27 00:19:04.566511 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-27 00:19:05.019690 | controller -> localhost | Generating public/private rsa key pair.
2025-09-27 00:19:05.019916 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_rsa.
2025-09-27 00:19:05.019946 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_rsa.pub.
2025-09-27 00:19:05.019968 | controller -> localhost | The key fingerprint is:
2025-09-27 00:19:05.019989 | controller -> localhost | SHA256:ZG8bdibai9ydUNU3KUhVk7e9k6FyZQIgD8ZHmMsIJuE zuul-build-sshkey
2025-09-27 00:19:05.020010 | controller -> localhost | The key's randomart image is:
2025-09-27 00:19:05.020030 | controller -> localhost | +---[RSA 2048]----+
2025-09-27 00:19:05.020049 | controller -> localhost | | ..   .++o.....o.|
2025-09-27 00:19:05.020069 | controller -> localhost | |.. o  .++....  o+|
2025-09-27 00:19:05.020088 | controller -> localhost | | Eo . o =. ....o*|
2025-09-27 00:19:05.020106 | controller -> localhost | |     . = .   o.=+|
2025-09-27 00:19:05.020125 | controller -> localhost | |        S * + = +|
2025-09-27 00:19:05.020153 | controller -> localhost | |         = O o + |
2025-09-27 00:19:05.020176 | controller -> localhost | |        . + o   .|
2025-09-27 00:19:05.020197 | controller -> localhost | |       . o + .   |
2025-09-27 00:19:05.020217 | controller -> localhost | |        o o o    |
2025-09-27 00:19:05.020240 | controller -> localhost | +----[SHA256]-----+
2025-09-27 00:19:05.020291 | controller -> localhost | ok: Runtime: 0:00:00.085689
2025-09-27 00:19:05.027067 | 
2025-09-27 00:19:05.027163 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-27 00:19:05.062045 | controller | ok
2025-09-27 00:19:05.072712 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-27 00:19:05.082165 | 
2025-09-27 00:19:05.082271 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-27 00:19:05.107513 | controller | skipping: Conditional result was False
2025-09-27 00:19:05.119578 | 
2025-09-27 00:19:05.119747 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-27 00:19:05.585795 | controller | changed
2025-09-27 00:19:05.594227 | 
2025-09-27 00:19:05.594382 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-27 00:19:05.818419 | controller | ok
2025-09-27 00:19:05.825198 | 
2025-09-27 00:19:05.825318 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-27 00:19:06.433085 | controller | changed
2025-09-27 00:19:06.443946 | 
2025-09-27 00:19:06.444187 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-27 00:19:07.062526 | controller | changed
2025-09-27 00:19:07.072070 | 
2025-09-27 00:19:07.072264 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-27 00:19:07.098242 | controller | skipping: Conditional result was False
2025-09-27 00:19:07.108869 | 
2025-09-27 00:19:07.109008 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-27 00:19:07.532311 | controller -> localhost | changed
2025-09-27 00:19:07.545623 | 
2025-09-27 00:19:07.545774 | TASK [add-build-sshkey : Add back temp key]
2025-09-27 00:19:07.836384 | controller -> localhost | Identity added: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_rsa (zuul-build-sshkey)
2025-09-27 00:19:07.836650 | controller -> localhost | ok: Runtime: 0:00:00.019187
2025-09-27 00:19:07.844422 | 
2025-09-27 00:19:07.844543 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-27 00:19:08.215244 | controller | ok
2025-09-27 00:19:08.222460 | 
2025-09-27 00:19:08.222565 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-27 00:19:08.267773 | controller | skipping: Conditional result was False
2025-09-27 00:19:08.280843 | 
2025-09-27 00:19:08.280963 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-27 00:19:08.312586 | controller | ok
2025-09-27 00:19:08.331334 | 
2025-09-27 00:19:08.331458 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-27 00:19:08.550180 | controller -> localhost | ok
2025-09-27 00:19:08.562308 | 
2025-09-27 00:19:08.562432 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-27 00:19:08.590313 | controller | ok
2025-09-27 00:19:08.614519 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-27 00:19:08.621466 | 
2025-09-27 00:19:08.621565 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-27 00:19:08.895996 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-27 00:19:08.896195 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_ecdsa.
2025-09-27 00:19:08.896224 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_ecdsa.pub.
2025-09-27 00:19:08.896256 | controller -> localhost | The key fingerprint is:
2025-09-27 00:19:08.896277 | controller -> localhost | SHA256:vHOcx/PUbn7PkySQmBQ9wx61P6ZpgmXlNUCm2H0CdS4 zuul-build-sshkey
2025-09-27 00:19:08.896296 | controller -> localhost | The key's randomart image is:
2025-09-27 00:19:08.896317 | controller -> localhost | +---[ECDSA 521]---+
2025-09-27 00:19:08.896335 | controller -> localhost | |         .+.+* . |
2025-09-27 00:19:08.896355 | controller -> localhost | |         .o*= =  |
2025-09-27 00:19:08.896374 | controller -> localhost | |        ..+o=E = |
2025-09-27 00:19:08.896393 | controller -> localhost | |       . o +o * .|
2025-09-27 00:19:08.896412 | controller -> localhost | |        S  o.. + |
2025-09-27 00:19:08.896430 | controller -> localhost | |         o+o .+o.|
2025-09-27 00:19:08.896447 | controller -> localhost | |        o.+.+++ o|
2025-09-27 00:19:08.896465 | controller -> localhost | |         o .o+ =o|
2025-09-27 00:19:08.896482 | controller -> localhost | |              .oO|
2025-09-27 00:19:08.896501 | controller -> localhost | +----[SHA256]-----+
2025-09-27 00:19:08.896546 | controller -> localhost | ok: Runtime: 0:00:00.016711
2025-09-27 00:19:08.903868 | 
2025-09-27 00:19:08.903994 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-27 00:19:08.927852 | controller | ok
2025-09-27 00:19:08.939060 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-27 00:19:08.951908 | 
2025-09-27 00:19:08.952037 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-27 00:19:08.976467 | controller | skipping: Conditional result was False
2025-09-27 00:19:08.983314 | 
2025-09-27 00:19:08.983780 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-27 00:19:09.245619 | controller | changed
2025-09-27 00:19:09.260013 | 
2025-09-27 00:19:09.260172 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-27 00:19:09.494711 | controller | ok
2025-09-27 00:19:09.507948 | 
2025-09-27 00:19:09.508106 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-27 00:19:10.112900 | controller | changed
2025-09-27 00:19:10.118898 | 
2025-09-27 00:19:10.118977 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-27 00:19:10.730843 | controller | changed
2025-09-27 00:19:10.740255 | 
2025-09-27 00:19:10.740441 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-27 00:19:10.756984 | controller | skipping: Conditional result was False
2025-09-27 00:19:10.768265 | 
2025-09-27 00:19:10.768508 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-27 00:19:10.997991 | controller -> localhost | changed
2025-09-27 00:19:11.010846 | 
2025-09-27 00:19:11.010945 | TASK [add-build-sshkey : Add back temp key]
2025-09-27 00:19:11.332839 | controller -> localhost | Identity added: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/02501938909d41159dc78ac4f100c340_id_ecdsa (zuul-build-sshkey)
2025-09-27 00:19:11.333082 | controller -> localhost | ok: Runtime: 0:00:00.007970
2025-09-27 00:19:11.343214 | 
2025-09-27 00:19:11.343338 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-27 00:19:11.593785 | controller | ok
2025-09-27 00:19:11.599569 | 
2025-09-27 00:19:11.599670 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-27 00:19:11.623472 | controller | skipping: Conditional result was False
2025-09-27 00:19:11.643270 | 
2025-09-27 00:19:11.643452 | TASK [include_role : remove-zuul-sshkey]
2025-09-27 00:19:11.659502 | controller | skipping: Conditional result was False
2025-09-27 00:19:11.669094 | 
2025-09-27 00:19:11.669230 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-27 00:19:11.902753 | controller | ok: "logs"
2025-09-27 00:19:11.903017 | controller | ok: All items complete
2025-09-27 00:19:11.903045 | 
2025-09-27 00:19:12.110415 | controller | ok: "artifacts"
2025-09-27 00:19:12.306753 | controller | ok: "docs"
2025-09-27 00:19:12.326631 | 
2025-09-27 00:19:12.326804 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-27 00:19:12.556995 | controller | changed: "logs"
2025-09-27 00:19:12.763159 | controller | changed: "artifacts"
2025-09-27 00:19:12.967350 | controller | changed: "docs"
2025-09-27 00:19:13.030856 | 
2025-09-27 00:19:13.031002 | PLAY RECAP
2025-09-27 00:19:13.031081 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-27 00:19:13.031136 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-27 00:19:13.031175 | 
2025-09-27 00:19:13.155821 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-27 00:19:13.157524 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-27 00:19:13.789742 | 
2025-09-27 00:19:13.789868 | PLAY [all]
2025-09-27 00:19:13.813365 | 
2025-09-27 00:19:13.813494 | TASK [Install binary dependencies]
2025-09-27 00:19:13.884039 | controller | ok
2025-09-27 00:19:13.904000 | 
2025-09-27 00:19:13.904144 | TASK [bindep : Include find tasks]
2025-09-27 00:19:13.933850 | controller | ok
2025-09-27 00:19:13.942794 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-27 00:19:13.950479 | 
2025-09-27 00:19:13.950598 | TASK [bindep : Look for bindep.txt]
2025-09-27 00:19:14.336879 | controller | ok
2025-09-27 00:19:14.351025 | 
2025-09-27 00:19:14.351223 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:19:14.368105 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.377969 | 
2025-09-27 00:19:14.378115 | TASK [bindep : Look for other-requirements.txt]
2025-09-27 00:19:14.595108 | controller | ok
2025-09-27 00:19:14.603357 | 
2025-09-27 00:19:14.603477 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:19:14.628714 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.643053 | 
2025-09-27 00:19:14.643249 | TASK [bindep : Look for bindep fallback file]
2025-09-27 00:19:14.669736 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.680900 | 
2025-09-27 00:19:14.681070 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:19:14.706420 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.716272 | 
2025-09-27 00:19:14.716409 | TASK [bindep : Include bindep tasks]
2025-09-27 00:19:14.741256 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.747864 | 
2025-09-27 00:19:14.747987 | TASK [bindep : Include install tasks]
2025-09-27 00:19:14.772367 | controller | skipping: Conditional result was False
2025-09-27 00:19:14.779124 | 
2025-09-27 00:19:14.779222 | LOOP [bindep : Include package tasks]
2025-09-27 00:19:14.839832 | 
2025-09-27 00:19:14.840042 | TASK [Run test-setup role]
2025-09-27 00:19:14.864232 | controller | ok
2025-09-27 00:19:14.890182 | 
2025-09-27 00:19:14.890350 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-27 00:19:15.109444 | controller | ok
2025-09-27 00:19:15.119986 | 
2025-09-27 00:19:15.120164 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-27 00:19:15.666622 | controller | skipping: Conditional result was False
2025-09-27 00:19:15.694876 | 
2025-09-27 00:19:15.694981 | PLAY RECAP
2025-09-27 00:19:15.695027 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-27 00:19:15.695048 | 
2025-09-27 00:19:15.834127 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-27 00:19:15.835230 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-27 00:19:16.450863 | 
2025-09-27 00:19:16.451016 | PLAY [controller]
2025-09-27 00:19:16.473131 | 
2025-09-27 00:19:16.473265 | TASK [Create the /root directory]
2025-09-27 00:19:16.921444 | controller | ok
2025-09-27 00:19:16.935503 | 
2025-09-27 00:19:16.935711 | TASK [Install glibc-langpack-en]
2025-09-27 00:19:20.922240 | controller | ok: Nothing to do
2025-09-27 00:19:20.928547 | 
2025-09-27 00:19:20.928629 | TASK [Ensure controller directory exists]
2025-09-27 00:19:21.141387 | controller | changed
2025-09-27 00:19:21.157523 | 
2025-09-27 00:19:21.157781 | TASK [Install container runtime]
2025-09-27 00:19:21.201867 | controller | ok
2025-09-27 00:19:21.242043 | 
2025-09-27 00:19:21.242181 | LOOP [ensure-podman : Find distribution installation]
2025-09-27 00:19:21.267398 | controller | ok: "/var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-27 00:19:21.275166 | controller | included: /var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-27 00:19:21.282395 | 
2025-09-27 00:19:21.282487 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-27 00:20:28.996380 | controller | changed
2025-09-27 00:20:29.010483 | 
2025-09-27 00:20:29.010640 | TASK [ensure-podman : Fetch podman version]
2025-09-27 00:20:29.584141 | controller | Client:       Podman Engine
2025-09-27 00:20:29.618967 | controller | Version:      4.6.2
2025-09-27 00:20:29.619006 | controller | API Version:  4.6.2
2025-09-27 00:20:29.619019 | controller | Go Version:   go1.19.12
2025-09-27 00:20:29.619044 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-27 00:20:29.619056 | controller | OS/Arch:      linux/amd64
2025-09-27 00:20:30.054266 | controller | ok: Runtime: 0:00:00.208656
2025-09-27 00:20:30.077607 | 
2025-09-27 00:20:30.077959 | TASK [ensure-podman : Print podman version installed]
2025-09-27 00:20:30.116359 | Podman version: Client:       Podman Engine
2025-09-27 00:20:30.116949 | Version:      4.6.2
2025-09-27 00:20:30.117070 | API Version:  4.6.2
2025-09-27 00:20:30.117121 | Go Version:   go1.19.12
2025-09-27 00:20:30.117165 | Built:        Mon Aug 28 19:38:31 2023
2025-09-27 00:20:30.117222 | OS/Arch:      linux/amd64
2025-09-27 00:20:30.134537 | 
2025-09-27 00:20:30.134801 | TASK [ensure-podman : Validate podman engine]
2025-09-27 00:20:30.682278 | controller | skipping: Conditional result was False
2025-09-27 00:20:30.689606 | 
2025-09-27 00:20:30.689702 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-27 00:20:30.714295 | controller | skipping: Conditional result was False
2025-09-27 00:20:30.734533 | 
2025-09-27 00:20:30.734732 | TASK [Ensure python3.8 is present]
2025-09-27 00:20:30.761364 | controller | skipping: Conditional result was False
2025-09-27 00:20:30.769876 | 
2025-09-27 00:20:30.770074 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-27 00:20:30.794918 | controller | ok
2025-09-27 00:20:30.817078 | 
2025-09-27 00:20:30.817271 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-27 00:20:32.241320 | controller | ok: Nothing to do
2025-09-27 00:20:32.250708 | 
2025-09-27 00:20:32.250885 | TASK [our-ensure-python : Also install python3-devel]
2025-09-27 00:20:40.956768 | controller | changed
2025-09-27 00:20:40.987527 | 
2025-09-27 00:20:40.987777 | TASK [Run ensure-virtualenv role]
2025-09-27 00:20:41.013932 | controller | ok
2025-09-27 00:20:41.044775 | 
2025-09-27 00:20:41.044910 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-27 00:20:41.261710 | controller | /usr/bin/virtualenv
2025-09-27 00:20:41.583324 | controller | ok: Runtime: 0:00:00.005461
2025-09-27 00:20:41.600139 | 
2025-09-27 00:20:41.600330 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-27 00:20:41.629388 | controller | skipping: Conditional result was False
2025-09-27 00:20:41.629770 | controller | ok: All items complete
2025-09-27 00:20:41.629800 | 
2025-09-27 00:20:41.695218 | 
2025-09-27 00:20:41.695500 | TASK [Find the full path of the Python interpreter]
2025-09-27 00:20:41.907442 | controller | /usr/bin/python3
2025-09-27 00:20:42.227344 | controller | ok
2025-09-27 00:20:42.241911 | 
2025-09-27 00:20:42.242148 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-27 00:20:43.116469 | controller | created virtual environment CPython3.11.0.final.0-64 in 536ms
2025-09-27 00:20:43.140714 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-27 00:20:43.140754 | 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-09-27 00:20:43.140767 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-27 00:20:43.140782 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-27 00:20:43.295278 | controller | changed
2025-09-27 00:20:43.301639 | 
2025-09-27 00:20:43.301734 | TASK [Set selinux package]
2025-09-27 00:20:43.331703 | controller | ok
2025-09-27 00:20:43.337266 | 
2025-09-27 00:20:43.337339 | TASK [Set selinux package (Fedora)]
2025-09-27 00:20:43.378691 | controller | ok
2025-09-27 00:20:43.384567 | 
2025-09-27 00:20:43.384652 | TASK [Install selinux into virtualenv]
2025-09-27 00:21:20.876893 | controller | Collecting selinux-please-lie-to-me
2025-09-27 00:21:33.249089 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-27 00:21:33.647645 | controller | Collecting setuptools<50.0.0
2025-09-27 00:21:33.658193 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-27 00:21:33.697202 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.7 MB/s eta 0:00:00
2025-09-27 00:21:33.785579 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-27 00:21:33.785830 | controller |   Attempting uninstall: setuptools
2025-09-27 00:21:33.788342 | controller |     Found existing installation: setuptools 62.6.0
2025-09-27 00:21:33.856182 | controller |     Uninstalling setuptools-62.6.0:
2025-09-27 00:21:33.865985 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-27 00:21:34.231389 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-27 00:21:45.501261 | controller |
2025-09-27 00:21:45.592647 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-27 00:21:45.592708 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-27 00:21:45.976761 | controller | ok: Runtime: 0:01:01.969172
2025-09-27 00:21:45.985003 | 
2025-09-27 00:21:45.985147 | TASK [Install pytest-forked into virtualenv]
2025-09-27 00:21:57.753928 | controller | Collecting pytest-forked
2025-09-27 00:22:33.905052 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-27 00:22:33.982471 | controller | Collecting py
2025-09-27 00:22:33.994109 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-27 00:22:34.018931 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.4 MB/s eta 0:00:00
2025-09-27 00:22:34.174764 | controller | Collecting pytest>=3.10
2025-09-27 00:22:34.179711 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-27 00:22:34.197857 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 24.5 MB/s eta 0:00:00
2025-09-27 00:22:34.235215 | controller | Collecting iniconfig>=1
2025-09-27 00:22:34.240136 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-27 00:22:34.301237 | controller | Collecting packaging>=20
2025-09-27 00:22:34.308620 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-27 00:22:34.320770 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.2 MB/s eta 0:00:00
2025-09-27 00:22:34.361896 | controller | Collecting pluggy<2,>=1.5
2025-09-27 00:22:34.367002 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-27 00:22:34.424646 | controller | Collecting pygments>=2.7.2
2025-09-27 00:22:34.430129 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-27 00:22:34.467403 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 38.6 MB/s eta 0:00:00
2025-09-27 00:22:34.555563 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-27 00:22:35.761887 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-09-27 00:22:35.770968 | controller |
2025-09-27 00:22:35.850483 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-27 00:22:35.850523 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-27 00:22:36.068247 | controller | ok: Runtime: 0:00:49.663518
2025-09-27 00:22:36.076957 | 
2025-09-27 00:22:36.077101 | TASK [Update pip]
2025-09-27 00:22:36.659847 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-27 00:22:46.259886 | controller | Collecting pip
2025-09-27 00:22:58.446066 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-27 00:22:58.520224 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.3 MB/s eta 0:00:00
2025-09-27 00:22:58.583941 | controller | Installing collected packages: pip
2025-09-27 00:22:58.584098 | controller |   Attempting uninstall: pip
2025-09-27 00:22:58.586253 | controller |     Found existing installation: pip 22.2.2
2025-09-27 00:22:58.734540 | controller |     Uninstalling pip-22.2.2:
2025-09-27 00:22:58.751692 | controller |       Successfully uninstalled pip-22.2.2
2025-09-27 00:22:59.588940 | controller | Successfully installed pip-25.2
2025-09-27 00:23:00.140573 | controller | ok: Runtime: 0:00:23.338362
2025-09-27 00:23:00.148464 | 
2025-09-27 00:23:00.148581 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-27 00:23:00.393515 | controller | changed
2025-09-27 00:23:00.400549 | 
2025-09-27 00:23:00.400661 | TASK [Install ansible into virtualenv]
2025-09-27 00:23:00.964947 | controller | Processing ./src/github.com/ansible/ansible
2025-09-27 00:23:00.968327 | controller |   Installing build dependencies: started
2025-09-27 00:23:23.369107 | controller |   Installing build dependencies: finished with status 'done'
2025-09-27 00:23:23.369694 | controller |   Getting requirements to build wheel: started
2025-09-27 00:23:24.137279 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-27 00:23:24.138376 | controller |   Preparing metadata (pyproject.toml): started
2025-09-27 00:23:24.610520 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-27 00:23:24.613413 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-09-27 00:23:24.617152 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-27 00:23:24.972982 | controller | ERROR
2025-09-27 00:23:24.973259 | controller | {
2025-09-27 00:23:24.973303 | controller |   "delta": "0:00:24.030538",
2025-09-27 00:23:24.973333 | controller |   "end": "2025-09-27 00:23:24.680944",
2025-09-27 00:23:24.973358 | controller |   "msg": "non-zero return code",
2025-09-27 00:23:24.973395 | controller |   "rc": 1,
2025-09-27 00:23:24.973420 | controller |   "start": "2025-09-27 00:23:00.650406"
2025-09-27 00:23:24.973443 | controller | }
failure
2025-09-27 00:23:24.975417 | 
2025-09-27 00:23:24.975494 | PLAY RECAP
2025-09-27 00:23:24.975568 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-27 00:23:24.975611 | 
2025-09-27 00:23:25.124172 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-27 00:23:25.125179 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-27 00:23:25.707838 | 
2025-09-27 00:23:25.707957 | PLAY [all]
2025-09-27 00:23:25.729647 | 
2025-09-27 00:23:25.729802 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-27 00:23:25.973733 | controller | changed: non-zero return code
2025-09-27 00:23:25.987121 | 
2025-09-27 00:23:25.987331 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-27 00:23:26.015109 | controller | skipping: Conditional result was False
2025-09-27 00:23:26.023851 | 
2025-09-27 00:23:26.023992 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-27 00:23:26.051235 | 
2025-09-27 00:23:26.051566 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-27 00:23:26.093425 | 
2025-09-27 00:23:26.093648 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-27 00:23:26.108432 | controller | skipping: Conditional result was False
2025-09-27 00:23:26.116255 | 
2025-09-27 00:23:26.116364 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-27 00:23:26.137818 | 
2025-09-27 00:23:26.138025 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-27 00:23:26.152135 | controller | skipping: Conditional result was False
2025-09-27 00:23:26.159442 | 
2025-09-27 00:23:26.159545 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-27 00:23:26.183052 | controller | skipping: Conditional result was False
2025-09-27 00:23:26.190281 | 
2025-09-27 00:23:26.190369 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-27 00:23:26.214977 | controller | skipping: Conditional result was False
2025-09-27 00:23:26.267311 | 
2025-09-27 00:23:26.267433 | PLAY RECAP
2025-09-27 00:23:26.267478 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-27 00:23:26.267498 | 
2025-09-27 00:23:26.367259 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-27 00:23:26.368217 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-27 00:23:27.071365 | 
2025-09-27 00:23:27.071507 | PLAY [all:!appliance*]
2025-09-27 00:23:27.110551 | 
2025-09-27 00:23:27.110719 | TASK [unregister the node]
2025-09-27 00:23:27.644422 | controller | skipping: Conditional result was False
2025-09-27 00:23:27.653518 | 
2025-09-27 00:23:27.653717 | TASK [include_role : fetch-output]
2025-09-27 00:23:27.685042 | controller | ok
2025-09-27 00:23:27.705084 | 
2025-09-27 00:23:27.705199 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-27 00:23:27.759970 | controller | skipping: Conditional result was False
2025-09-27 00:23:27.766938 | 
2025-09-27 00:23:27.767027 | TASK [fetch-output : Set log path for single node]
2025-09-27 00:23:27.806350 | controller | ok
2025-09-27 00:23:27.812033 | 
2025-09-27 00:23:27.812108 | LOOP [fetch-output : Ensure local output dirs]
2025-09-27 00:23:28.277056 | controller -> localhost | ok: "/var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/logs"
2025-09-27 00:23:28.552122 | controller -> localhost | changed: "/var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/artifacts"
2025-09-27 00:23:28.836622 | controller -> localhost | changed: "/var/lib/zuul/builds/02501938909d41159dc78ac4f100c340/work/docs"
2025-09-27 00:23:28.850516 | 
2025-09-27 00:23:28.850625 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-27 00:23:29.527553 | controller | changed:
2025-09-27 00:23:29.527808 | controller | .d..t...... ./
2025-09-27 00:23:29.527840 | controller | cd+++++++++ controller/
2025-09-27 00:23:29.527876 | controller | changed: All items complete
2025-09-27 00:23:29.527897 | 
2025-09-27 00:23:29.988822 | controller | changed: .d..t...... ./
2025-09-27 00:23:30.462883 | controller | changed: .d..t...... ./
2025-09-27 00:23:30.504115 | 
2025-09-27 00:23:30.504283 | TASK [include_role : fetch-output-openshift]
2025-09-27 00:23:30.529815 | controller | skipping: Conditional result was False
2025-09-27 00:23:30.545467 | 
2025-09-27 00:23:30.545666 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-27 00:23:30.595449 | controller | skipping: Conditional result was False
2025-09-27 00:23:30.608648 | controller | skipping: Conditional result was False
2025-09-27 00:23:30.647144 | 
2025-09-27 00:23:30.647307 | PLAY [localhost]
2025-09-27 00:23:30.659552 | 
2025-09-27 00:23:30.659641 | TASK [Run Zuul manifest role]
2025-09-27 00:23:30.678404 | localhost | ok
2025-09-27 00:23:30.692765 | 
2025-09-27 00:23:30.692882 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-27 00:23:31.072013 | localhost | changed
2025-09-27 00:23:31.077014 | 
2025-09-27 00:23:31.077087 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-27 00:23:31.105536 | localhost | ok
2025-09-27 00:23:31.113630 | 
2025-09-27 00:23:31.113719 | TASK [Set zuul-log-path fact]
2025-09-27 00:23:31.131574 | localhost | ok
2025-09-27 00:23:31.145381 | 
2025-09-27 00:23:31.145474 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-27 00:23:31.175854 | localhost | ok
2025-09-27 00:23:31.196464 | 
2025-09-27 00:23:31.196618 | LOOP [Run upload-logs-swift role]
2025-09-27 00:23:31.222077 | localhost | Output suppressed because no_log was given
2025-09-27 00:23:31.256290 | 
2025-09-27 00:23:31.256414 | TASK [Set zuul-log-path fact]
2025-09-27 00:23:31.280444 | localhost | skipping: Conditional result was False
2025-09-27 00:23:31.285774 | 
2025-09-27 00:23:31.285887 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-27 00:23:31.714651 | localhost -> localhost | ok: Runtime: 0:00:00.005058
2025-09-27 00:23:31.721693 | 
2025-09-27 00:23:31.721814 | TASK [upload-logs-swift : Upload logs to swift]