2025-10-18 00:16:05.419947 | Job console starting...
2025-10-18 00:16:05.428786 | Updating repositories
2025-10-18 00:16:05.538445 | Preparing job workspace
2025-10-18 00:16:09.092532 | Running Ansible setup...
2025-10-18 00:16:14.265540 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-18 00:16:14.873812 | 
2025-10-18 00:16:14.873935 | PLAY [localhost]
2025-10-18 00:16:14.886757 | 
2025-10-18 00:16:14.886835 | TASK [Gathering Facts]
2025-10-18 00:16:15.873417 | localhost | ok
2025-10-18 00:16:15.898321 | 
2025-10-18 00:16:15.898482 | TASK [Setup log path fact]
2025-10-18 00:16:15.918125 | localhost | ok
2025-10-18 00:16:15.934565 | 
2025-10-18 00:16:15.934656 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-18 00:16:15.964295 | localhost | ok
2025-10-18 00:16:15.974834 | 
2025-10-18 00:16:15.974922 | TASK [emit-job-header : Print job information]
2025-10-18 00:16:16.013753 | # Job Information
2025-10-18 00:16:16.013899 | Ansible Version: 2.15.12
2025-10-18 00:16:16.013930 | Job: ansible-test-sanity-docker-milestone
2025-10-18 00:16:16.013951 | Pipeline: periodic
2025-10-18 00:16:16.013970 | Executor: ze02.softwarefactory-project.io
2025-10-18 00:16:16.013988 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-18 00:16:16.014010 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/a56/ansible/a5644e250991497787057a67476a1976/
2025-10-18 00:16:16.014029 | Event ID: 475bf33318134110a1dbccf99c35efa3
2025-10-18 00:16:16.017591 | 
2025-10-18 00:16:16.017651 | LOOP [emit-job-header : Print node information]
2025-10-18 00:16:16.109724 | localhost | ok:
2025-10-18 00:16:16.109939 | localhost | # Node Information
2025-10-18 00:16:16.109966 | localhost | Inventory Hostname: controller
2025-10-18 00:16:16.109986 | localhost | Hostname: np0005493994
2025-10-18 00:16:16.110005 | localhost | Username: zuul
2025-10-18 00:16:16.110153 | localhost | Distro: Fedora 37
2025-10-18 00:16:16.110185 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-10-18 00:16:16.110204 | localhost | Region: ca-ymq-1
2025-10-18 00:16:16.110222 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-18 00:16:16.110238 | localhost | Product Name: OpenStack Nova
2025-10-18 00:16:16.110254 | localhost | Interface IP: 162.253.55.221
2025-10-18 00:16:16.118870 | 
2025-10-18 00:16:16.118935 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-18 00:16:16.508087 | localhost -> localhost | changed
2025-10-18 00:16:16.513512 | 
2025-10-18 00:16:16.513577 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-18 00:16:17.382019 | localhost -> localhost | changed
2025-10-18 00:16:17.404142 | 
2025-10-18 00:16:17.404214 | PLAY [all:!appliance*]
2025-10-18 00:16:17.420919 | 
2025-10-18 00:16:17.420985 | TASK [include_role : start-zuul-console]
2025-10-18 00:16:17.439641 | controller | ok
2025-10-18 00:16:17.453996 | 
2025-10-18 00:16:17.454081 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-18 00:16:17.812893 | controller | ok
2025-10-18 00:16:17.841754 | 
2025-10-18 00:16:17.841847 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-18 00:16:18.912600 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-18 00:16:18.924358 | 
2025-10-18 00:16:18.924474 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-18 00:16:19.476791 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.492218 | 
2025-10-18 00:16:19.492362 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-18 00:16:19.529510 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.544011 | 
2025-10-18 00:16:19.544149 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-18 00:16:19.581934 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.614525 | 
2025-10-18 00:16:19.615079 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-18 00:16:19.651118 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.660051 | 
2025-10-18 00:16:19.660140 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-18 00:16:19.695193 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.703865 | 
2025-10-18 00:16:19.703956 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-18 00:16:19.729249 | controller | skipping: Conditional result was False
2025-10-18 00:16:19.746409 | 
2025-10-18 00:16:19.746494 | TASK [Disable Fedora Modular]
2025-10-18 00:16:20.002508 | controller | changed
2025-10-18 00:16:20.009929 | 
2025-10-18 00:16:20.010045 | TASK [Enable EPEL]
2025-10-18 00:16:20.054879 | controller | skipping: Conditional result was False
2025-10-18 00:16:20.061824 | 
2025-10-18 00:16:20.061913 | TASK [Register the RHEL node]
2025-10-18 00:16:20.611556 | 
2025-10-18 00:16:20.611882 | TASK [Show the subscription-manager status]
2025-10-18 00:16:21.199412 | controller | skipping: Conditional result was False
2025-10-18 00:16:21.214533 | 
2025-10-18 00:16:21.214712 | TASK [Enable EPEL on RHEL]
2025-10-18 00:16:21.779147 | controller | skipping: Conditional result was False
2025-10-18 00:16:21.785253 | 
2025-10-18 00:16:21.785340 | TASK [Install git and tox]
2025-10-18 00:18:16.364919 | controller | changed
2025-10-18 00:18:16.374331 | 
2025-10-18 00:18:16.374529 | TASK [include_role : prepare-workspace]
2025-10-18 00:18:16.405588 | controller | ok
2025-10-18 00:18:16.446071 | 
2025-10-18 00:18:16.446223 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-18 00:18:16.682790 | controller | ok
2025-10-18 00:18:16.691938 | 
2025-10-18 00:18:16.692027 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-18 00:18:29.138968 | controller | Output suppressed because no_log was given
2025-10-18 00:18:29.185456 | 
2025-10-18 00:18:29.185590 | TASK [include_role : prepare-workspace-openshift]
2025-10-18 00:18:29.213118 | controller | skipping: Conditional result was False
2025-10-18 00:18:29.245712 | 
2025-10-18 00:18:29.245801 | PLAY [all:!appliance]
2025-10-18 00:18:29.269261 | 
2025-10-18 00:18:29.269395 | TASK [Run add-build-sshkey role (RSA)]
2025-10-18 00:18:29.299187 | controller | ok
2025-10-18 00:18:29.313643 | 
2025-10-18 00:18:29.313727 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-18 00:18:29.603261 | controller -> localhost | ok
2025-10-18 00:18:29.617562 | 
2025-10-18 00:18:29.617754 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-18 00:18:29.657849 | controller | ok
2025-10-18 00:18:29.690257 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-18 00:18:29.704161 | 
2025-10-18 00:18:29.704299 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-18 00:18:30.271239 | controller -> localhost | Generating public/private rsa key pair.
2025-10-18 00:18:30.271453 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_rsa.
2025-10-18 00:18:30.271482 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_rsa.pub.
2025-10-18 00:18:30.271502 | controller -> localhost | The key fingerprint is:
2025-10-18 00:18:30.271521 | controller -> localhost | SHA256:/T55uOKIPll/tPKZDn9IngPd7S3gBLMMAmsxqSPl0CA zuul-build-sshkey
2025-10-18 00:18:30.271539 | controller -> localhost | The key's randomart image is:
2025-10-18 00:18:30.271557 | controller -> localhost | +---[RSA 2048]----+
2025-10-18 00:18:30.271575 | controller -> localhost | |Eo   .           |
2025-10-18 00:18:30.271593 | controller -> localhost | |o o =            |
2025-10-18 00:18:30.271610 | controller -> localhost | | + . =           |
2025-10-18 00:18:30.271627 | controller -> localhost | |. + o . ..o      |
2025-10-18 00:18:30.271644 | controller -> localhost | | . o   .So.= . . |
2025-10-18 00:18:30.271685 | controller -> localhost | |        . +.* . .|
2025-10-18 00:18:30.271712 | controller -> localhost | |       o ..B.B ..|
2025-10-18 00:18:30.271733 | controller -> localhost | |      o. .++%o+ o|
2025-10-18 00:18:30.271751 | controller -> localhost | |     .o....*O* . |
2025-10-18 00:18:30.271770 | controller -> localhost | +----[SHA256]-----+
2025-10-18 00:18:30.271820 | controller -> localhost | ok: Runtime: 0:00:00.188210
2025-10-18 00:18:30.280173 | 
2025-10-18 00:18:30.280243 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-18 00:18:30.311393 | controller | ok
2025-10-18 00:18:30.322249 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-18 00:18:30.331531 | 
2025-10-18 00:18:30.331595 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-18 00:18:30.355961 | controller | skipping: Conditional result was False
2025-10-18 00:18:30.363035 | 
2025-10-18 00:18:30.363101 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-18 00:18:30.811158 | controller | changed
2025-10-18 00:18:30.824069 | 
2025-10-18 00:18:30.824204 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-18 00:18:31.088000 | controller | ok
2025-10-18 00:18:31.101889 | 
2025-10-18 00:18:31.102029 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-18 00:18:31.764577 | controller | changed
2025-10-18 00:18:31.780569 | 
2025-10-18 00:18:31.780736 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-18 00:18:32.456756 | controller | changed
2025-10-18 00:18:32.471133 | 
2025-10-18 00:18:32.471268 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-18 00:18:32.508820 | controller | skipping: Conditional result was False
2025-10-18 00:18:32.524496 | 
2025-10-18 00:18:32.524630 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-18 00:18:33.002070 | controller -> localhost | changed
2025-10-18 00:18:33.033536 | 
2025-10-18 00:18:33.033729 | TASK [add-build-sshkey : Add back temp key]
2025-10-18 00:18:33.330830 | controller -> localhost | Identity added: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_rsa (zuul-build-sshkey)
2025-10-18 00:18:33.331419 | controller -> localhost | ok: Runtime: 0:00:00.013679
2025-10-18 00:18:33.351470 | 
2025-10-18 00:18:33.351634 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-18 00:18:33.758589 | controller | ok
2025-10-18 00:18:33.773350 | 
2025-10-18 00:18:33.773469 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-18 00:18:33.801130 | controller | skipping: Conditional result was False
2025-10-18 00:18:33.819319 | 
2025-10-18 00:18:33.819417 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-18 00:18:33.852839 | controller | ok
2025-10-18 00:18:33.877055 | 
2025-10-18 00:18:33.877147 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-18 00:18:34.147174 | controller -> localhost | ok
2025-10-18 00:18:34.162567 | 
2025-10-18 00:18:34.162773 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-18 00:18:34.196251 | controller | ok
2025-10-18 00:18:34.218004 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-18 00:18:34.226630 | 
2025-10-18 00:18:34.226737 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-18 00:18:34.505970 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-18 00:18:34.506209 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_ecdsa.
2025-10-18 00:18:34.506239 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_ecdsa.pub.
2025-10-18 00:18:34.506269 | controller -> localhost | The key fingerprint is:
2025-10-18 00:18:34.506289 | controller -> localhost | SHA256:26xj+FGdvCss9KdgTPHlJsW4lOos9apCMkX5zKYH4Sk zuul-build-sshkey
2025-10-18 00:18:34.506307 | controller -> localhost | The key's randomart image is:
2025-10-18 00:18:34.506326 | controller -> localhost | +---[ECDSA 521]---+
2025-10-18 00:18:34.506343 | controller -> localhost | |     .           |
2025-10-18 00:18:34.506359 | controller -> localhost | |    +      +     |
2025-10-18 00:18:34.506376 | controller -> localhost | |   o *  . + +    |
2025-10-18 00:18:34.506395 | controller -> localhost | |  E = =  = B .   |
2025-10-18 00:18:34.506413 | controller -> localhost | |   o +  S = *    |
2025-10-18 00:18:34.506429 | controller -> localhost | |  o o .*.* o .   |
2025-10-18 00:18:34.506475 | controller -> localhost | |   + ..oOo+ .    |
2025-10-18 00:18:34.506494 | controller -> localhost | |    . .o+=+ ..   |
2025-10-18 00:18:34.506510 | controller -> localhost | |     ..++o.+.    |
2025-10-18 00:18:34.506527 | controller -> localhost | +----[SHA256]-----+
2025-10-18 00:18:34.506582 | controller -> localhost | ok: Runtime: 0:00:00.008637
2025-10-18 00:18:34.513781 | 
2025-10-18 00:18:34.513844 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-18 00:18:34.534029 | controller | ok
2025-10-18 00:18:34.542094 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-18 00:18:34.552946 | 
2025-10-18 00:18:34.553037 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-18 00:18:34.567203 | controller | skipping: Conditional result was False
2025-10-18 00:18:34.574617 | 
2025-10-18 00:18:34.574697 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-18 00:18:34.839814 | controller | changed
2025-10-18 00:18:34.854349 | 
2025-10-18 00:18:34.854487 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-18 00:18:35.089160 | controller | ok
2025-10-18 00:18:35.105825 | 
2025-10-18 00:18:35.105962 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-18 00:18:35.728253 | controller | changed
2025-10-18 00:18:35.741965 | 
2025-10-18 00:18:35.742111 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-18 00:18:36.413167 | controller | changed
2025-10-18 00:18:36.428610 | 
2025-10-18 00:18:36.428784 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-18 00:18:36.455363 | controller | skipping: Conditional result was False
2025-10-18 00:18:36.510400 | 
2025-10-18 00:18:36.510540 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-18 00:18:36.769372 | controller -> localhost | changed
2025-10-18 00:18:36.797652 | 
2025-10-18 00:18:36.797974 | TASK [add-build-sshkey : Add back temp key]
2025-10-18 00:18:37.132923 | controller -> localhost | Identity added: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/a5644e250991497787057a67476a1976_id_ecdsa (zuul-build-sshkey)
2025-10-18 00:18:37.133115 | controller -> localhost | ok: Runtime: 0:00:00.013469
2025-10-18 00:18:37.139634 | 
2025-10-18 00:18:37.139721 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-18 00:18:37.371323 | controller | ok
2025-10-18 00:18:37.387387 | 
2025-10-18 00:18:37.387581 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-18 00:18:37.425400 | controller | skipping: Conditional result was False
2025-10-18 00:18:37.451030 | 
2025-10-18 00:18:37.451176 | TASK [include_role : remove-zuul-sshkey]
2025-10-18 00:18:37.479577 | controller | skipping: Conditional result was False
2025-10-18 00:18:37.497085 | 
2025-10-18 00:18:37.497227 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-18 00:18:37.744219 | controller | ok: "logs"
2025-10-18 00:18:37.744658 | controller | ok: All items complete
2025-10-18 00:18:37.744756 | 
2025-10-18 00:18:37.951159 | controller | ok: "artifacts"
2025-10-18 00:18:38.149553 | controller | ok: "docs"
2025-10-18 00:18:38.165239 | 
2025-10-18 00:18:38.165443 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-18 00:18:38.413066 | controller | changed: "logs"
2025-10-18 00:18:38.611836 | controller | changed: "artifacts"
2025-10-18 00:18:38.814742 | controller | changed: "docs"
2025-10-18 00:18:38.878335 | 
2025-10-18 00:18:38.878428 | PLAY RECAP
2025-10-18 00:18:38.878486 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-18 00:18:38.878523 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-18 00:18:38.878550 | 
2025-10-18 00:18:38.992078 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-18 00:18:38.992910 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-18 00:18:39.568904 | 
2025-10-18 00:18:39.569042 | PLAY [all]
2025-10-18 00:18:39.590132 | 
2025-10-18 00:18:39.590221 | TASK [Install binary dependencies]
2025-10-18 00:18:39.629322 | controller | ok
2025-10-18 00:18:39.648169 | 
2025-10-18 00:18:39.648257 | TASK [bindep : Include find tasks]
2025-10-18 00:18:39.676845 | controller | ok
2025-10-18 00:18:39.684401 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-18 00:18:39.690465 | 
2025-10-18 00:18:39.690526 | TASK [bindep : Look for bindep.txt]
2025-10-18 00:18:40.031651 | controller | ok
2025-10-18 00:18:40.044238 | 
2025-10-18 00:18:40.044391 | TASK [bindep : Define bindep_file fact]
2025-10-18 00:18:40.070940 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.083485 | 
2025-10-18 00:18:40.083626 | TASK [bindep : Look for other-requirements.txt]
2025-10-18 00:18:40.324229 | controller | ok
2025-10-18 00:18:40.335943 | 
2025-10-18 00:18:40.336082 | TASK [bindep : Define bindep_file fact]
2025-10-18 00:18:40.362417 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.374807 | 
2025-10-18 00:18:40.374946 | TASK [bindep : Look for bindep fallback file]
2025-10-18 00:18:40.401445 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.416624 | 
2025-10-18 00:18:40.416797 | TASK [bindep : Define bindep_file fact]
2025-10-18 00:18:40.443001 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.455327 | 
2025-10-18 00:18:40.455459 | TASK [bindep : Include bindep tasks]
2025-10-18 00:18:40.481590 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.493966 | 
2025-10-18 00:18:40.494104 | TASK [bindep : Include install tasks]
2025-10-18 00:18:40.520247 | controller | skipping: Conditional result was False
2025-10-18 00:18:40.532834 | 
2025-10-18 00:18:40.532969 | LOOP [bindep : Include package tasks]
2025-10-18 00:18:40.602401 | 
2025-10-18 00:18:40.602691 | TASK [Run test-setup role]
2025-10-18 00:18:40.633207 | controller | ok
2025-10-18 00:18:40.661356 | 
2025-10-18 00:18:40.661456 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-18 00:18:40.890807 | controller | ok
2025-10-18 00:18:40.904115 | 
2025-10-18 00:18:40.904254 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-18 00:18:41.454915 | controller | skipping: Conditional result was False
2025-10-18 00:18:41.509363 | 
2025-10-18 00:18:41.509447 | PLAY RECAP
2025-10-18 00:18:41.509500 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-18 00:18:41.509527 | 
2025-10-18 00:18:41.601717 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-18 00:18:41.603453 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-18 00:18:42.214348 | 
2025-10-18 00:18:42.214479 | PLAY [controller]
2025-10-18 00:18:42.235741 | 
2025-10-18 00:18:42.235858 | TASK [Create the /root directory]
2025-10-18 00:18:42.621408 | controller | ok
2025-10-18 00:18:42.627233 | 
2025-10-18 00:18:42.627303 | TASK [Install glibc-langpack-en]
2025-10-18 00:18:46.584041 | controller | ok: Nothing to do
2025-10-18 00:18:46.598586 | 
2025-10-18 00:18:46.598788 | TASK [Ensure controller directory exists]
2025-10-18 00:18:46.833910 | controller | changed
2025-10-18 00:18:46.847596 | 
2025-10-18 00:18:46.847805 | TASK [Install container runtime]
2025-10-18 00:18:46.929172 | controller | ok
2025-10-18 00:18:46.991192 | 
2025-10-18 00:18:46.991356 | LOOP [ensure-podman : Find distribution installation]
2025-10-18 00:18:47.034255 | controller | ok: "/var/lib/zuul/builds/a5644e250991497787057a67476a1976/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-18 00:18:47.043290 | controller | included: /var/lib/zuul/builds/a5644e250991497787057a67476a1976/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-18 00:18:47.049966 | 
2025-10-18 00:18:47.050034 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-18 00:20:12.595969 | controller | changed
2025-10-18 00:20:12.614258 | 
2025-10-18 00:20:12.614474 | TASK [ensure-podman : Fetch podman version]
2025-10-18 00:20:14.226819 | controller | Client:       Podman Engine
2025-10-18 00:20:14.226978 | controller | Version:      4.6.2
2025-10-18 00:20:14.227064 | controller | API Version:  4.6.2
2025-10-18 00:20:14.227156 | controller | Go Version:   go1.19.12
2025-10-18 00:20:14.227260 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-18 00:20:14.227352 | controller | OS/Arch:      linux/amd64
2025-10-18 00:20:14.659106 | controller | ok: Runtime: 0:00:01.216011
2025-10-18 00:20:14.674382 | 
2025-10-18 00:20:14.674536 | TASK [ensure-podman : Print podman version installed]
2025-10-18 00:20:14.714841 | Podman version: Client:       Podman Engine
2025-10-18 00:20:14.715080 | Version:      4.6.2
2025-10-18 00:20:14.715139 | API Version:  4.6.2
2025-10-18 00:20:14.715182 | Go Version:   go1.19.12
2025-10-18 00:20:14.715225 | Built:        Mon Aug 28 19:38:31 2023
2025-10-18 00:20:14.715264 | OS/Arch:      linux/amd64
2025-10-18 00:20:14.729174 | 
2025-10-18 00:20:14.729336 | TASK [ensure-podman : Validate podman engine]
2025-10-18 00:20:15.277791 | controller | skipping: Conditional result was False
2025-10-18 00:20:15.292062 | 
2025-10-18 00:20:15.292452 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-18 00:20:15.309854 | controller | skipping: Conditional result was False
2025-10-18 00:20:15.337243 | 
2025-10-18 00:20:15.337411 | TASK [Ensure python3.8 is present]
2025-10-18 00:20:15.355050 | controller | skipping: Conditional result was False
2025-10-18 00:20:15.365009 | 
2025-10-18 00:20:15.365099 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-18 00:20:15.388516 | controller | ok
2025-10-18 00:20:15.416533 | 
2025-10-18 00:20:15.416632 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-18 00:20:16.883095 | controller | ok: Nothing to do
2025-10-18 00:20:16.897417 | 
2025-10-18 00:20:16.897560 | TASK [our-ensure-python : Also install python3-devel]
2025-10-18 00:20:33.503418 | controller | changed
2025-10-18 00:20:33.529301 | 
2025-10-18 00:20:33.529437 | TASK [Run ensure-virtualenv role]
2025-10-18 00:20:33.554211 | controller | ok
2025-10-18 00:20:33.589523 | 
2025-10-18 00:20:33.589720 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-18 00:20:33.808956 | controller | /usr/bin/virtualenv
2025-10-18 00:20:34.124836 | controller | ok: Runtime: 0:00:00.006012
2025-10-18 00:20:34.132996 | 
2025-10-18 00:20:34.133080 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-18 00:20:34.156365 | controller | skipping: Conditional result was False
2025-10-18 00:20:34.156840 | controller | ok: All items complete
2025-10-18 00:20:34.156902 | 
2025-10-18 00:20:34.173654 | 
2025-10-18 00:20:34.173825 | TASK [Find the full path of the Python interpreter]
2025-10-18 00:20:34.483063 | controller | /usr/bin/python3
2025-10-18 00:20:34.769035 | controller | ok
2025-10-18 00:20:34.781765 | 
2025-10-18 00:20:34.781915 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-18 00:20:36.210970 | controller | created virtual environment CPython3.11.0.final.0-64 in 1041ms
2025-10-18 00:20:36.236850 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-18 00:20:36.237829 | 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-10-18 00:20:36.237844 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-18 00:20:36.237858 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-18 00:20:36.348985 | controller | changed
2025-10-18 00:20:36.364834 | 
2025-10-18 00:20:36.365014 | TASK [Set selinux package]
2025-10-18 00:20:36.404430 | controller | ok
2025-10-18 00:20:36.416556 | 
2025-10-18 00:20:36.416761 | TASK [Set selinux package (Fedora)]
2025-10-18 00:20:36.477727 | controller | ok
2025-10-18 00:20:36.489496 | 
2025-10-18 00:20:36.489635 | TASK [Install selinux into virtualenv]
2025-10-18 00:21:14.102370 | controller | Collecting selinux-please-lie-to-me
2025-10-18 00:21:26.354657 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-18 00:21:26.676975 | controller | Collecting setuptools<50.0.0
2025-10-18 00:21:26.682791 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-18 00:21:26.748551 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 13.3 MB/s eta 0:00:00
2025-10-18 00:21:26.836316 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-18 00:21:26.836562 | controller |   Attempting uninstall: setuptools
2025-10-18 00:21:26.839206 | controller |     Found existing installation: setuptools 62.6.0
2025-10-18 00:21:26.913762 | controller |     Uninstalling setuptools-62.6.0:
2025-10-18 00:21:26.922578 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-18 00:21:27.296782 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-18 00:21:38.783205 | controller |
2025-10-18 00:21:38.878761 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-18 00:21:38.878808 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-18 00:21:39.260427 | controller | ok: Runtime: 0:01:02.138254
2025-10-18 00:21:39.273646 | 
2025-10-18 00:21:39.273824 | TASK [Install pytest-forked into virtualenv]
2025-10-18 00:21:50.996293 | controller | Collecting pytest-forked
2025-10-18 00:22:03.340077 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-18 00:22:03.387769 | controller | Collecting py
2025-10-18 00:22:03.392777 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-18 00:22:03.415167 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.3 MB/s eta 0:00:00
2025-10-18 00:22:03.543348 | controller | Collecting pytest>=3.10
2025-10-18 00:22:03.546989 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-18 00:22:03.572958 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 15.7 MB/s eta 0:00:00
2025-10-18 00:22:03.611750 | controller | Collecting iniconfig>=1
2025-10-18 00:22:03.616942 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-18 00:22:03.664411 | controller | Collecting packaging>=20
2025-10-18 00:22:03.667776 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-18 00:22:03.675332 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.7 MB/s eta 0:00:00
2025-10-18 00:22:03.707736 | controller | Collecting pluggy<2,>=1.5
2025-10-18 00:22:03.712854 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-18 00:22:03.764630 | controller | Collecting pygments>=2.7.2
2025-10-18 00:22:03.770557 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-18 00:22:03.830942 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 21.6 MB/s eta 0:00:00
2025-10-18 00:22:03.902846 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-18 00:22:05.010935 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-18 00:22:05.019877 | controller |
2025-10-18 00:22:05.098191 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-18 00:22:05.098240 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-18 00:22:05.346046 | controller | ok: Runtime: 0:00:25.571651
2025-10-18 00:22:05.359776 | 
2025-10-18 00:22:05.359912 | TASK [Update pip]
2025-10-18 00:22:05.909001 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-18 00:22:13.673947 | controller | Collecting pip
2025-10-18 00:22:25.916337 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-18 00:22:25.994715 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.3 MB/s eta 0:00:00
2025-10-18 00:22:26.061983 | controller | Installing collected packages: pip
2025-10-18 00:22:26.062225 | controller |   Attempting uninstall: pip
2025-10-18 00:22:26.064559 | controller |     Found existing installation: pip 22.2.2
2025-10-18 00:22:26.222956 | controller |     Uninstalling pip-22.2.2:
2025-10-18 00:22:26.238975 | controller |       Successfully uninstalled pip-22.2.2
2025-10-18 00:22:27.061248 | controller | Successfully installed pip-25.2
2025-10-18 00:22:27.431813 | controller | ok: Runtime: 0:00:21.546971
2025-10-18 00:22:27.444339 | 
2025-10-18 00:22:27.444470 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-18 00:22:27.688298 | controller | changed
2025-10-18 00:22:27.700204 | 
2025-10-18 00:22:27.700334 | TASK [Install ansible into virtualenv]
2025-10-18 00:22:28.307367 | controller | Processing ./src/github.com/ansible/ansible
2025-10-18 00:22:28.311946 | controller |   Installing build dependencies: started
2025-10-18 00:22:50.804246 | controller |   Installing build dependencies: finished with status 'done'
2025-10-18 00:22:50.805463 | controller |   Getting requirements to build wheel: started
2025-10-18 00:22:51.548666 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-18 00:22:51.549569 | controller |   Preparing metadata (pyproject.toml): started
2025-10-18 00:22:52.021708 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-18 00:22:52.027336 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-10-18 00:22:52.031218 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-18 00:22:52.286362 | controller | ERROR
2025-10-18 00:22:52.286545 | controller | {
2025-10-18 00:22:52.286601 | controller |   "delta": "0:00:24.123418",
2025-10-18 00:22:52.286641 | controller |   "end": "2025-10-18 00:22:52.097255",
2025-10-18 00:22:52.286719 | controller |   "msg": "non-zero return code",
2025-10-18 00:22:52.286773 | controller |   "rc": 1,
2025-10-18 00:22:52.286807 | controller |   "start": "2025-10-18 00:22:27.973837"
2025-10-18 00:22:52.286840 | controller | }
failure
2025-10-18 00:22:52.289095 | 
2025-10-18 00:22:52.289186 | PLAY RECAP
2025-10-18 00:22:52.289270 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-18 00:22:52.289325 | 
2025-10-18 00:22:52.431608 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-18 00:22:52.433438 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-18 00:22:53.019734 | 
2025-10-18 00:22:53.019840 | PLAY [all]
2025-10-18 00:22:53.040239 | 
2025-10-18 00:22:53.040339 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-18 00:22:53.354288 | controller | changed: non-zero return code
2025-10-18 00:22:53.367030 | 
2025-10-18 00:22:53.367186 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-18 00:22:53.396927 | controller | skipping: Conditional result was False
2025-10-18 00:22:53.411199 | 
2025-10-18 00:22:53.411346 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-18 00:22:53.454336 | 
2025-10-18 00:22:53.454594 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-18 00:22:53.492633 | 
2025-10-18 00:22:53.492953 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-18 00:22:53.520285 | controller | skipping: Conditional result was False
2025-10-18 00:22:53.530766 | 
2025-10-18 00:22:53.530861 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-18 00:22:53.564997 | 
2025-10-18 00:22:53.565173 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-18 00:22:53.591225 | controller | skipping: Conditional result was False
2025-10-18 00:22:53.599517 | 
2025-10-18 00:22:53.599608 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-18 00:22:53.625815 | controller | skipping: Conditional result was False
2025-10-18 00:22:53.639509 | 
2025-10-18 00:22:53.639657 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-18 00:22:53.667548 | controller | skipping: Conditional result was False
2025-10-18 00:22:53.707427 | 
2025-10-18 00:22:53.707608 | PLAY RECAP
2025-10-18 00:22:53.707699 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-18 00:22:53.707738 | 
2025-10-18 00:22:53.882453 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-18 00:22:53.883301 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-18 00:22:54.516917 | 
2025-10-18 00:22:54.517049 | PLAY [all:!appliance*]
2025-10-18 00:22:54.538773 | 
2025-10-18 00:22:54.538884 | TASK [unregister the node]
2025-10-18 00:22:55.070830 | controller | skipping: Conditional result was False
2025-10-18 00:22:55.083889 | 
2025-10-18 00:22:55.084057 | TASK [include_role : fetch-output]
2025-10-18 00:22:55.133527 | controller | ok
2025-10-18 00:22:55.181086 | 
2025-10-18 00:22:55.181295 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-18 00:22:55.259596 | controller | skipping: Conditional result was False
2025-10-18 00:22:55.273320 | 
2025-10-18 00:22:55.273472 | TASK [fetch-output : Set log path for single node]
2025-10-18 00:22:55.329293 | controller | ok
2025-10-18 00:22:55.337241 | 
2025-10-18 00:22:55.337331 | LOOP [fetch-output : Ensure local output dirs]
2025-10-18 00:22:55.750451 | controller -> localhost | ok: "/var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/logs"
2025-10-18 00:22:56.029250 | controller -> localhost | changed: "/var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/artifacts"
2025-10-18 00:22:56.249807 | controller -> localhost | changed: "/var/lib/zuul/builds/a5644e250991497787057a67476a1976/work/docs"
2025-10-18 00:22:56.268111 | 
2025-10-18 00:22:56.268195 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-18 00:22:57.039488 | controller | changed:
2025-10-18 00:22:57.039883 | controller | .d..t...... ./
2025-10-18 00:22:57.039948 | controller | cd+++++++++ controller/
2025-10-18 00:22:57.040020 | controller | changed: All items complete
2025-10-18 00:22:57.040065 | 
2025-10-18 00:22:57.587091 | controller | changed: .d..t...... ./
2025-10-18 00:22:58.042071 | controller | changed: .d..t...... ./
2025-10-18 00:22:58.076347 | 
2025-10-18 00:22:58.076508 | TASK [include_role : fetch-output-openshift]
2025-10-18 00:22:58.093255 | controller | skipping: Conditional result was False
2025-10-18 00:22:58.102754 | 
2025-10-18 00:22:58.102850 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-18 00:22:58.127708 | controller | skipping: Conditional result was False
2025-10-18 00:22:58.135735 | controller | skipping: Conditional result was False
2025-10-18 00:22:58.175963 | 
2025-10-18 00:22:58.176078 | PLAY [localhost]
2025-10-18 00:22:58.191568 | 
2025-10-18 00:22:58.191642 | TASK [Run Zuul manifest role]
2025-10-18 00:22:58.209252 | localhost | ok
2025-10-18 00:22:58.222848 | 
2025-10-18 00:22:58.222911 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-18 00:22:58.645993 | localhost | changed
2025-10-18 00:22:58.651238 | 
2025-10-18 00:22:58.651316 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-18 00:22:58.679832 | localhost | ok
2025-10-18 00:22:58.687592 | 
2025-10-18 00:22:58.687651 | TASK [Set zuul-log-path fact]
2025-10-18 00:22:58.705577 | localhost | ok
2025-10-18 00:22:58.719831 | 
2025-10-18 00:22:58.719922 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-18 00:22:58.747950 | localhost | ok
2025-10-18 00:22:58.756747 | 
2025-10-18 00:22:58.756820 | LOOP [Run upload-logs-swift role]
2025-10-18 00:22:58.801391 | localhost | Output suppressed because no_log was given
2025-10-18 00:22:58.843282 | 
2025-10-18 00:22:58.843402 | TASK [Set zuul-log-path fact]
2025-10-18 00:22:58.878171 | localhost | skipping: Conditional result was False
2025-10-18 00:22:58.890284 | 
2025-10-18 00:22:58.890459 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-18 00:22:59.337709 | localhost -> localhost | ok: Runtime: 0:00:00.005169
2025-10-18 00:22:59.386297 | 
2025-10-18 00:22:59.386423 | TASK [upload-logs-swift : Upload logs to swift]