2025-12-30 00:18:43.734101 | Job console starting... 2025-12-30 00:18:43.742725 | Updating repositories 2025-12-30 00:18:43.849902 | Preparing job workspace 2025-12-30 00:18:47.437069 | Running Ansible setup... 2025-12-30 00:18:52.409627 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-30 00:18:56.521030 | 2025-12-30 00:18:56.521225 | PLAY [localhost] 2025-12-30 00:18:56.531320 | 2025-12-30 00:18:56.531461 | TASK [Gathering Facts] 2025-12-30 00:18:57.636169 | localhost | ok 2025-12-30 00:18:57.672879 | 2025-12-30 00:18:57.673098 | TASK [Setup log path fact] 2025-12-30 00:18:57.699143 | localhost | ok 2025-12-30 00:18:57.727791 | 2025-12-30 00:18:57.727932 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-30 00:18:57.758057 | localhost | ok 2025-12-30 00:18:57.767797 | 2025-12-30 00:18:57.767901 | TASK [emit-job-header : Print job information] 2025-12-30 00:18:57.797287 | # Job Information 2025-12-30 00:18:57.797742 | Ansible Version: 2.15.12 2025-12-30 00:18:57.797793 | Job: ansible-test-sanity-docker-milestone 2025-12-30 00:18:57.797824 | Pipeline: periodic 2025-12-30 00:18:57.797848 | Executor: ze04.softwarefactory-project.io 2025-12-30 00:18:57.797871 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-30 00:18:57.797893 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/eb8/ansible/eb88f81a833843e28e7d581397e7ecc1/ 2025-12-30 00:18:57.797912 | Event ID: 3253ff496aa2446d86190793a25a6b45 2025-12-30 00:18:57.803872 | 2025-12-30 00:18:57.804132 | LOOP [emit-job-header : Print node information] 2025-12-30 00:18:57.907944 | localhost | ok: 2025-12-30 00:18:57.908710 | localhost | # Node Information 2025-12-30 00:18:57.908792 | localhost | Inventory Hostname: controller 2025-12-30 00:18:57.908838 | localhost | Hostname: np0005572399 2025-12-30 00:18:57.908880 | localhost | Username: zuul 2025-12-30 00:18:57.908923 | localhost | Distro: Fedora 37 2025-12-30 00:18:57.908963 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-30 00:18:57.909002 | localhost | Region: ca-ymq-1 2025-12-30 00:18:57.909039 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-30 00:18:57.909075 | localhost | Product Name: OpenStack Nova 2025-12-30 00:18:57.909112 | localhost | Interface IP: 162.253.55.42 2025-12-30 00:18:57.932269 | 2025-12-30 00:18:57.932491 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-30 00:18:58.347863 | localhost -> localhost | changed 2025-12-30 00:18:58.355065 | 2025-12-30 00:18:58.355192 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-30 00:18:59.268859 | localhost -> localhost | changed 2025-12-30 00:18:59.305174 | 2025-12-30 00:18:59.305334 | PLAY [all:!appliance*] 2025-12-30 00:18:59.332125 | 2025-12-30 00:18:59.332268 | TASK [include_role : start-zuul-console] 2025-12-30 00:18:59.353539 | controller | ok 2025-12-30 00:18:59.369227 | 2025-12-30 00:18:59.369300 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-30 00:18:59.771259 | controller | ok 2025-12-30 00:18:59.809725 | 2025-12-30 00:18:59.810043 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-30 00:19:22.099454 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-30 00:19:22.114776 | 2025-12-30 00:19:22.115001 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-30 00:19:22.669624 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.680674 | 2025-12-30 00:19:22.680810 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-30 00:19:22.696252 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.707651 | 2025-12-30 00:19:22.707930 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-30 00:19:22.734577 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.744486 | 2025-12-30 00:19:22.744643 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-30 00:19:22.761130 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.772016 | 2025-12-30 00:19:22.772154 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-30 00:19:22.798139 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.807666 | 2025-12-30 00:19:22.807790 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-30 00:19:22.832931 | controller | skipping: Conditional result was False 2025-12-30 00:19:22.850130 | 2025-12-30 00:19:22.850250 | TASK [Disable Fedora Modular] 2025-12-30 00:19:23.172481 | controller | changed 2025-12-30 00:19:23.178786 | 2025-12-30 00:19:23.178870 | TASK [Enable EPEL] 2025-12-30 00:19:23.205469 | controller | skipping: Conditional result was False 2025-12-30 00:19:23.215099 | 2025-12-30 00:19:23.215305 | TASK [Register the RHEL node] 2025-12-30 00:19:23.766901 | 2025-12-30 00:19:23.767109 | TASK [Show the subscription-manager status] 2025-12-30 00:19:24.315279 | controller | skipping: Conditional result was False 2025-12-30 00:19:24.327317 | 2025-12-30 00:19:24.327615 | TASK [Enable EPEL on RHEL] 2025-12-30 00:19:24.896299 | controller | skipping: Conditional result was False 2025-12-30 00:19:24.902808 | 2025-12-30 00:19:24.902896 | TASK [Install git and tox] 2025-12-30 00:20:26.039196 | controller | changed 2025-12-30 00:20:26.052942 | 2025-12-30 00:20:26.053068 | TASK [include_role : prepare-workspace] 2025-12-30 00:20:26.096170 | controller | ok 2025-12-30 00:20:26.134737 | 2025-12-30 00:20:26.134866 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-30 00:20:26.378188 | controller | ok 2025-12-30 00:20:26.392894 | 2025-12-30 00:20:26.393035 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-30 00:20:39.073701 | controller | Output suppressed because no_log was given 2025-12-30 00:20:39.093112 | 2025-12-30 00:20:39.093313 | TASK [include_role : prepare-workspace-openshift] 2025-12-30 00:20:39.122842 | controller | skipping: Conditional result was False 2025-12-30 00:20:39.158956 | 2025-12-30 00:20:39.159074 | PLAY [all:!appliance] 2025-12-30 00:20:39.186499 | 2025-12-30 00:20:39.186694 | TASK [Run add-build-sshkey role (RSA)] 2025-12-30 00:20:39.222009 | controller | ok 2025-12-30 00:20:39.243626 | 2025-12-30 00:20:39.243850 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-30 00:20:39.528031 | controller -> localhost | ok 2025-12-30 00:20:39.593540 | 2025-12-30 00:20:39.593740 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-30 00:20:39.627544 | controller | ok 2025-12-30 00:20:39.644190 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-30 00:20:39.651511 | 2025-12-30 00:20:39.651590 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-30 00:20:40.146015 | controller -> localhost | Generating public/private rsa key pair. 2025-12-30 00:20:40.146330 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_rsa. 2025-12-30 00:20:40.146361 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_rsa.pub. 2025-12-30 00:20:40.146383 | controller -> localhost | The key fingerprint is: 2025-12-30 00:20:40.146403 | controller -> localhost | SHA256:ZtYhT6GE6BHgNG7krquzkJ4f3hHLdiIiUSozpEbETlA zuul-build-sshkey 2025-12-30 00:20:40.146423 | controller -> localhost | The key's randomart image is: 2025-12-30 00:20:40.146442 | controller -> localhost | +---[RSA 2048]----+ 2025-12-30 00:20:40.146460 | controller -> localhost | |+oE..o .. . | 2025-12-30 00:20:40.146479 | controller -> localhost | |.O .o .. . . | 2025-12-30 00:20:40.146496 | controller -> localhost | |oo*. . o o | 2025-12-30 00:20:40.146514 | controller -> localhost | |+* . = . | 2025-12-30 00:20:40.146531 | controller -> localhost | |B.. . S o | 2025-12-30 00:20:40.146558 | controller -> localhost | |o* . o+ | 2025-12-30 00:20:40.146581 | controller -> localhost | |=. o * . | 2025-12-30 00:20:40.146600 | controller -> localhost | |=.+ = + | 2025-12-30 00:20:40.146618 | controller -> localhost | |==.o . | 2025-12-30 00:20:40.146639 | controller -> localhost | +----[SHA256]-----+ 2025-12-30 00:20:40.146708 | controller -> localhost | ok: Runtime: 0:00:00.081959 2025-12-30 00:20:40.155630 | 2025-12-30 00:20:40.155716 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-30 00:20:40.192438 | controller | ok 2025-12-30 00:20:40.211876 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-30 00:20:40.225831 | 2025-12-30 00:20:40.225974 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-30 00:20:40.243168 | controller | skipping: Conditional result was False 2025-12-30 00:20:40.253567 | 2025-12-30 00:20:40.253727 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-30 00:20:40.650132 | controller | changed 2025-12-30 00:20:40.663751 | 2025-12-30 00:20:40.665648 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-30 00:20:40.905767 | controller | ok 2025-12-30 00:20:40.914914 | 2025-12-30 00:20:40.915007 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-30 00:20:41.591581 | controller | changed 2025-12-30 00:20:41.606887 | 2025-12-30 00:20:41.606980 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-30 00:20:42.258154 | controller | changed 2025-12-30 00:20:42.272234 | 2025-12-30 00:20:42.272369 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-30 00:20:42.310204 | controller | skipping: Conditional result was False 2025-12-30 00:20:42.326314 | 2025-12-30 00:20:42.326456 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-30 00:20:42.732972 | controller -> localhost | changed 2025-12-30 00:20:42.747780 | 2025-12-30 00:20:42.747870 | TASK [add-build-sshkey : Add back temp key] 2025-12-30 00:20:43.038353 | controller -> localhost | Identity added: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_rsa (zuul-build-sshkey) 2025-12-30 00:20:43.038618 | controller -> localhost | ok: Runtime: 0:00:00.010185 2025-12-30 00:20:43.046367 | 2025-12-30 00:20:43.046440 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-30 00:20:43.359789 | controller | ok 2025-12-30 00:20:43.375989 | 2025-12-30 00:20:43.376085 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-30 00:20:43.424026 | controller | skipping: Conditional result was False 2025-12-30 00:20:43.443975 | 2025-12-30 00:20:43.444078 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-30 00:20:43.501430 | controller | ok 2025-12-30 00:20:43.527312 | 2025-12-30 00:20:43.527412 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-30 00:20:43.787285 | controller -> localhost | ok 2025-12-30 00:20:43.795392 | 2025-12-30 00:20:43.795521 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-30 00:20:43.839799 | controller | ok 2025-12-30 00:20:43.851159 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-30 00:20:43.857666 | 2025-12-30 00:20:43.857746 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-30 00:20:44.516561 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-30 00:20:44.516889 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_ecdsa. 2025-12-30 00:20:44.516931 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_ecdsa.pub. 2025-12-30 00:20:44.516973 | controller -> localhost | The key fingerprint is: 2025-12-30 00:20:44.517002 | controller -> localhost | SHA256:R9hcSaMGSM4wlw4t9m7++djWz8pskXHljN5K80NfQKg zuul-build-sshkey 2025-12-30 00:20:44.517036 | controller -> localhost | The key's randomart image is: 2025-12-30 00:20:44.517063 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-30 00:20:44.517094 | controller -> localhost | | oooo. .+o | 2025-12-30 00:20:44.517120 | controller -> localhost | | +*+ = oo.. .| 2025-12-30 00:20:44.517145 | controller -> localhost | | . =o . *. . = | 2025-12-30 00:20:44.517168 | controller -> localhost | | o oE . + o| 2025-12-30 00:20:44.517193 | controller -> localhost | | . S . = o | 2025-12-30 00:20:44.517219 | controller -> localhost | | o . o +.o| 2025-12-30 00:20:44.517244 | controller -> localhost | | o . o.+o| 2025-12-30 00:20:44.517268 | controller -> localhost | | . +.oo...o| 2025-12-30 00:20:44.517293 | controller -> localhost | | .+oo.+oo .| 2025-12-30 00:20:44.517317 | controller -> localhost | +----[SHA256]-----+ 2025-12-30 00:20:44.517388 | controller -> localhost | ok: Runtime: 0:00:00.317929 2025-12-30 00:20:44.528124 | 2025-12-30 00:20:44.528216 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-30 00:20:44.563831 | controller | ok 2025-12-30 00:20:44.579394 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-30 00:20:44.593189 | 2025-12-30 00:20:44.593281 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-30 00:20:44.629391 | controller | skipping: Conditional result was False 2025-12-30 00:20:44.638549 | 2025-12-30 00:20:44.638616 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-30 00:20:44.924632 | controller | changed 2025-12-30 00:20:44.931223 | 2025-12-30 00:20:44.931290 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-30 00:20:45.150799 | controller | ok 2025-12-30 00:20:45.160099 | 2025-12-30 00:20:45.160195 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-30 00:20:45.818643 | controller | changed 2025-12-30 00:20:45.832928 | 2025-12-30 00:20:45.833112 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-30 00:20:46.486567 | controller | changed 2025-12-30 00:20:46.495761 | 2025-12-30 00:20:46.495837 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-30 00:20:46.532305 | controller | skipping: Conditional result was False 2025-12-30 00:20:46.540890 | 2025-12-30 00:20:46.540984 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-30 00:20:46.851875 | controller -> localhost | changed 2025-12-30 00:20:46.864946 | 2025-12-30 00:20:46.865056 | TASK [add-build-sshkey : Add back temp key] 2025-12-30 00:20:47.165607 | controller -> localhost | Identity added: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/eb88f81a833843e28e7d581397e7ecc1_id_ecdsa (zuul-build-sshkey) 2025-12-30 00:20:47.166145 | controller -> localhost | ok: Runtime: 0:00:00.015587 2025-12-30 00:20:47.191838 | 2025-12-30 00:20:47.192039 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-30 00:20:47.417121 | controller | ok 2025-12-30 00:20:47.432989 | 2025-12-30 00:20:47.433178 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-30 00:20:47.482977 | controller | skipping: Conditional result was False 2025-12-30 00:20:47.512494 | 2025-12-30 00:20:47.512802 | TASK [include_role : remove-zuul-sshkey] 2025-12-30 00:20:47.540349 | controller | skipping: Conditional result was False 2025-12-30 00:20:47.550927 | 2025-12-30 00:20:47.551029 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-30 00:20:47.791650 | controller | ok: "logs" 2025-12-30 00:20:47.792375 | controller | ok: All items complete 2025-12-30 00:20:47.792442 | 2025-12-30 00:20:47.968262 | controller | ok: "artifacts" 2025-12-30 00:20:48.167183 | controller | ok: "docs" 2025-12-30 00:20:48.188210 | 2025-12-30 00:20:48.188399 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-30 00:20:48.434644 | controller | changed: "logs" 2025-12-30 00:20:48.635290 | controller | changed: "artifacts" 2025-12-30 00:20:48.838470 | controller | changed: "docs" 2025-12-30 00:20:48.898148 | 2025-12-30 00:20:48.898318 | PLAY RECAP 2025-12-30 00:20:48.898384 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-30 00:20:48.898423 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-30 00:20:48.898457 | 2025-12-30 00:20:49.078645 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-30 00:20:49.080560 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-30 00:20:49.697896 | 2025-12-30 00:20:49.698084 | PLAY [all] 2025-12-30 00:20:49.727303 | 2025-12-30 00:20:49.727477 | TASK [Install binary dependencies] 2025-12-30 00:20:49.779958 | controller | ok 2025-12-30 00:20:49.801736 | 2025-12-30 00:20:49.801859 | TASK [bindep : Include find tasks] 2025-12-30 00:20:49.840937 | controller | ok 2025-12-30 00:20:49.856180 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-30 00:20:49.868511 | 2025-12-30 00:20:49.868915 | TASK [bindep : Look for bindep.txt] 2025-12-30 00:20:50.226071 | controller | ok 2025-12-30 00:20:50.240174 | 2025-12-30 00:20:50.240331 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:20:50.270992 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.291254 | 2025-12-30 00:20:50.291489 | TASK [bindep : Look for other-requirements.txt] 2025-12-30 00:20:50.531207 | controller | ok 2025-12-30 00:20:50.545760 | 2025-12-30 00:20:50.545937 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:20:50.584528 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.594454 | 2025-12-30 00:20:50.594566 | TASK [bindep : Look for bindep fallback file] 2025-12-30 00:20:50.642074 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.652851 | 2025-12-30 00:20:50.653070 | TASK [bindep : Define bindep_file fact] 2025-12-30 00:20:50.679227 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.690491 | 2025-12-30 00:20:50.690627 | TASK [bindep : Include bindep tasks] 2025-12-30 00:20:50.736813 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.745795 | 2025-12-30 00:20:50.745929 | TASK [bindep : Include install tasks] 2025-12-30 00:20:50.771544 | controller | skipping: Conditional result was False 2025-12-30 00:20:50.781622 | 2025-12-30 00:20:50.781858 | LOOP [bindep : Include package tasks] 2025-12-30 00:20:50.860476 | 2025-12-30 00:20:50.860660 | TASK [Run test-setup role] 2025-12-30 00:20:50.882161 | controller | ok 2025-12-30 00:20:50.899429 | 2025-12-30 00:20:50.899508 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-30 00:20:51.110662 | controller | ok 2025-12-30 00:20:51.125464 | 2025-12-30 00:20:51.125619 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-30 00:20:51.679730 | controller | skipping: Conditional result was False 2025-12-30 00:20:51.736738 | 2025-12-30 00:20:51.736861 | PLAY RECAP 2025-12-30 00:20:51.736919 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-30 00:20:51.736947 | 2025-12-30 00:20:51.868214 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-30 00:20:51.869184 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-30 00:20:52.571025 | 2025-12-30 00:20:52.571240 | PLAY [controller] 2025-12-30 00:20:52.595096 | 2025-12-30 00:20:52.595262 | TASK [Create the /root directory] 2025-12-30 00:20:52.985519 | controller | ok 2025-12-30 00:20:53.000379 | 2025-12-30 00:20:53.000596 | TASK [Install glibc-langpack-en] 2025-12-30 00:20:57.007510 | controller | ok: Nothing to do 2025-12-30 00:20:57.020373 | 2025-12-30 00:20:57.020540 | TASK [Ensure controller directory exists] 2025-12-30 00:20:57.231148 | controller | changed 2025-12-30 00:20:57.241135 | 2025-12-30 00:20:57.241249 | TASK [Install container runtime] 2025-12-30 00:20:57.307907 | controller | ok 2025-12-30 00:20:57.362366 | 2025-12-30 00:20:57.362518 | LOOP [ensure-podman : Find distribution installation] 2025-12-30 00:20:57.387284 | controller | ok: "/var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-30 00:20:57.405005 | controller | included: /var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-30 00:20:57.411833 | 2025-12-30 00:20:57.411921 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-30 00:22:03.405646 | controller | changed 2025-12-30 00:22:03.420665 | 2025-12-30 00:22:03.420981 | TASK [ensure-podman : Fetch podman version] 2025-12-30 00:22:03.992982 | controller | Client: Podman Engine 2025-12-30 00:22:03.993085 | controller | Version: 4.6.2 2025-12-30 00:22:03.993131 | controller | API Version: 4.6.2 2025-12-30 00:22:03.993173 | controller | Go Version: go1.19.12 2025-12-30 00:22:03.993406 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-30 00:22:03.993453 | controller | OS/Arch: linux/amd64 2025-12-30 00:22:04.472751 | controller | ok: Runtime: 0:00:00.184668 2025-12-30 00:22:04.488822 | 2025-12-30 00:22:04.489134 | TASK [ensure-podman : Print podman version installed] 2025-12-30 00:22:04.533140 | Podman version: Client: Podman Engine 2025-12-30 00:22:04.533448 | Version: 4.6.2 2025-12-30 00:22:04.533509 | API Version: 4.6.2 2025-12-30 00:22:04.533553 | Go Version: go1.19.12 2025-12-30 00:22:04.533593 | Built: Mon Aug 28 19:38:31 2023 2025-12-30 00:22:04.533634 | OS/Arch: linux/amd64 2025-12-30 00:22:04.546884 | 2025-12-30 00:22:04.547063 | TASK [ensure-podman : Validate podman engine] 2025-12-30 00:22:05.097413 | controller | skipping: Conditional result was False 2025-12-30 00:22:05.113604 | 2025-12-30 00:22:05.113814 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-30 00:22:05.132959 | controller | skipping: Conditional result was False 2025-12-30 00:22:05.157170 | 2025-12-30 00:22:05.157288 | TASK [Ensure python3.8 is present] 2025-12-30 00:22:05.183944 | controller | skipping: Conditional result was False 2025-12-30 00:22:05.193840 | 2025-12-30 00:22:05.193930 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-30 00:22:05.218422 | controller | ok 2025-12-30 00:22:05.253626 | 2025-12-30 00:22:05.253756 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-30 00:22:06.692597 | controller | ok: Nothing to do 2025-12-30 00:22:06.708091 | 2025-12-30 00:22:06.708302 | TASK [our-ensure-python : Also install python3-devel] 2025-12-30 00:22:16.576104 | controller | changed 2025-12-30 00:22:16.592167 | 2025-12-30 00:22:16.592270 | TASK [Run ensure-virtualenv role] 2025-12-30 00:22:16.627236 | controller | ok 2025-12-30 00:22:16.660986 | 2025-12-30 00:22:16.661102 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-30 00:22:16.896468 | controller | /usr/bin/virtualenv 2025-12-30 00:22:17.195924 | controller | ok: Runtime: 0:00:00.004933 2025-12-30 00:22:17.205247 | 2025-12-30 00:22:17.205337 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-30 00:22:17.254442 | controller | skipping: Conditional result was False 2025-12-30 00:22:17.255056 | controller | ok: All items complete 2025-12-30 00:22:17.255125 | 2025-12-30 00:22:17.284365 | 2025-12-30 00:22:17.284589 | TASK [Find the full path of the Python interpreter] 2025-12-30 00:22:17.583957 | controller | /usr/bin/python3 2025-12-30 00:22:17.901986 | controller | ok 2025-12-30 00:22:17.910402 | 2025-12-30 00:22:17.910508 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-30 00:22:18.816874 | controller | created virtual environment CPython3.11.0.final.0-64 in 495ms 2025-12-30 00:22:18.842663 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-30 00:22:18.843033 | 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-30 00:22:18.843336 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-30 00:22:18.843613 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-30 00:22:18.950944 | controller | changed 2025-12-30 00:22:18.966440 | 2025-12-30 00:22:18.966665 | TASK [Set selinux package] 2025-12-30 00:22:19.002536 | controller | ok 2025-12-30 00:22:19.009741 | 2025-12-30 00:22:19.009930 | TASK [Set selinux package (Fedora)] 2025-12-30 00:22:19.052401 | controller | ok 2025-12-30 00:22:19.058002 | 2025-12-30 00:22:19.058086 | TASK [Install selinux into virtualenv] 2025-12-30 00:22:56.475021 | controller | Collecting selinux-please-lie-to-me 2025-12-30 00:23:09.057151 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-30 00:23:09.370996 | controller | Collecting setuptools<50.0.0 2025-12-30 00:23:09.377883 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-30 00:23:09.458439 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 12.7 MB/s eta 0:00:00 2025-12-30 00:23:09.534788 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-30 00:23:09.535001 | controller | Attempting uninstall: setuptools 2025-12-30 00:23:09.537339 | controller | Found existing installation: setuptools 62.6.0 2025-12-30 00:23:09.595727 | controller | Uninstalling setuptools-62.6.0: 2025-12-30 00:23:09.603454 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-30 00:23:09.942329 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-30 00:23:21.112119 | controller | 2025-12-30 00:23:21.191650 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-30 00:23:21.191692 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-30 00:23:21.624158 | controller | ok: Runtime: 0:01:01.894098 2025-12-30 00:23:21.637314 | 2025-12-30 00:23:21.637455 | TASK [Install pytest-forked into virtualenv] 2025-12-30 00:23:31.317504 | controller | Collecting pytest-forked 2025-12-30 00:23:43.688262 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-30 00:23:43.739796 | controller | Collecting py 2025-12-30 00:23:43.748301 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-30 00:23:43.770678 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.6 MB/s eta 0:00:00 2025-12-30 00:23:43.885524 | controller | Collecting pytest>=3.10 2025-12-30 00:23:43.891193 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-30 00:23:43.906889 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 29.4 MB/s eta 0:00:00 2025-12-30 00:23:43.943238 | controller | Collecting iniconfig>=1.0.1 2025-12-30 00:23:43.946994 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-30 00:23:43.995026 | controller | Collecting packaging>=22 2025-12-30 00:23:43.998883 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-30 00:23:44.006496 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.3 MB/s eta 0:00:00 2025-12-30 00:23:44.041131 | controller | Collecting pluggy<2,>=1.5 2025-12-30 00:23:44.046187 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-30 00:23:44.096640 | controller | Collecting pygments>=2.7.2 2025-12-30 00:23:44.100101 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-30 00:23:44.120931 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 66.3 MB/s eta 0:00:00 2025-12-30 00:23:44.190569 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-30 00:23:45.274717 | 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-30 00:23:45.283441 | controller | 2025-12-30 00:23:45.357740 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-30 00:23:45.357800 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-30 00:23:45.707772 | controller | ok: Runtime: 0:00:23.492456 2025-12-30 00:23:45.717894 | 2025-12-30 00:23:45.718081 | TASK [Update pip] 2025-12-30 00:23:46.251421 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-30 00:24:08.027246 | controller | Collecting pip 2025-12-30 00:24:20.228404 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-30 00:24:20.280078 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 37.6 MB/s eta 0:00:00 2025-12-30 00:24:20.342697 | controller | Installing collected packages: pip 2025-12-30 00:24:20.342940 | controller | Attempting uninstall: pip 2025-12-30 00:24:20.345142 | controller | Found existing installation: pip 22.2.2 2025-12-30 00:24:20.481056 | controller | Uninstalling pip-22.2.2: 2025-12-30 00:24:20.496027 | controller | Successfully uninstalled pip-22.2.2 2025-12-30 00:24:21.299302 | controller | Successfully installed pip-25.3 2025-12-30 00:24:21.786518 | controller | ok: Runtime: 0:00:35.421704 2025-12-30 00:24:21.793936 | 2025-12-30 00:24:21.794007 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-30 00:24:22.019557 | controller | changed 2025-12-30 00:24:22.026294 | 2025-12-30 00:24:22.026442 | TASK [Install ansible into virtualenv] 2025-12-30 00:24:22.575495 | controller | Processing ./src/github.com/ansible/ansible 2025-12-30 00:24:22.578747 | controller | Installing build dependencies: started 2025-12-30 00:24:57.537277 | controller | Installing build dependencies: finished with status 'done' 2025-12-30 00:24:57.537856 | controller | Getting requirements to build wheel: started 2025-12-30 00:24:58.271710 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-30 00:24:58.273367 | controller | Preparing metadata (pyproject.toml): started 2025-12-30 00:24:58.729790 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-30 00:24:58.735869 | 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-30 00:24:58.739173 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-30 00:24:59.123012 | controller | ERROR 2025-12-30 00:24:59.123464 | controller | { 2025-12-30 00:24:59.123555 | controller | "delta": "0:00:36.520055", 2025-12-30 00:24:59.123613 | controller | "end": "2025-12-30 00:24:58.807965", 2025-12-30 00:24:59.123654 | controller | "msg": "non-zero return code", 2025-12-30 00:24:59.123761 | controller | "rc": 1, 2025-12-30 00:24:59.123805 | controller | "start": "2025-12-30 00:24:22.287910" 2025-12-30 00:24:59.123841 | controller | } failure 2025-12-30 00:24:59.126826 | 2025-12-30 00:24:59.126925 | PLAY RECAP 2025-12-30 00:24:59.127011 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-30 00:24:59.127056 | 2025-12-30 00:24:59.264589 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-30 00:24:59.266880 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-30 00:25:00.016460 | 2025-12-30 00:25:00.016610 | PLAY [all] 2025-12-30 00:25:00.039827 | 2025-12-30 00:25:00.039996 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-30 00:25:00.311154 | controller | changed: non-zero return code 2025-12-30 00:25:00.323603 | 2025-12-30 00:25:00.323883 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-30 00:25:00.352379 | controller | skipping: Conditional result was False 2025-12-30 00:25:00.366605 | 2025-12-30 00:25:00.366817 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-30 00:25:00.409462 | 2025-12-30 00:25:00.409820 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-30 00:25:00.448416 | 2025-12-30 00:25:00.448644 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-30 00:25:00.475188 | controller | skipping: Conditional result was False 2025-12-30 00:25:00.485963 | 2025-12-30 00:25:00.486071 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-30 00:25:00.520012 | 2025-12-30 00:25:00.520220 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-30 00:25:00.545596 | controller | skipping: Conditional result was False 2025-12-30 00:25:00.555668 | 2025-12-30 00:25:00.555788 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-30 00:25:00.581219 | controller | skipping: Conditional result was False 2025-12-30 00:25:00.590945 | 2025-12-30 00:25:00.591057 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-30 00:25:00.617033 | controller | skipping: Conditional result was False 2025-12-30 00:25:00.666087 | 2025-12-30 00:25:00.666225 | PLAY RECAP 2025-12-30 00:25:00.666269 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-30 00:25:00.666290 | 2025-12-30 00:25:00.843152 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-30 00:25:00.845577 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-30 00:25:01.489356 | 2025-12-30 00:25:01.489524 | PLAY [all:!appliance*] 2025-12-30 00:25:01.514981 | 2025-12-30 00:25:01.515109 | TASK [unregister the node] 2025-12-30 00:25:02.048060 | controller | skipping: Conditional result was False 2025-12-30 00:25:02.058394 | 2025-12-30 00:25:02.058522 | TASK [include_role : fetch-output] 2025-12-30 00:25:02.092396 | controller | ok 2025-12-30 00:25:02.120566 | 2025-12-30 00:25:02.120772 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-30 00:25:02.167302 | controller | skipping: Conditional result was False 2025-12-30 00:25:02.174864 | 2025-12-30 00:25:02.174990 | TASK [fetch-output : Set log path for single node] 2025-12-30 00:25:02.218811 | controller | ok 2025-12-30 00:25:02.226745 | 2025-12-30 00:25:02.226889 | LOOP [fetch-output : Ensure local output dirs] 2025-12-30 00:25:02.673116 | controller -> localhost | ok: "/var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/logs" 2025-12-30 00:25:02.913696 | controller -> localhost | changed: "/var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/artifacts" 2025-12-30 00:25:03.170732 | controller -> localhost | changed: "/var/lib/zuul/builds/eb88f81a833843e28e7d581397e7ecc1/work/docs" 2025-12-30 00:25:03.184501 | 2025-12-30 00:25:03.184649 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-30 00:25:03.937739 | controller | changed: 2025-12-30 00:25:03.938130 | controller | .d..t...... ./ 2025-12-30 00:25:03.938191 | controller | cd+++++++++ controller/ 2025-12-30 00:25:03.938258 | controller | changed: All items complete 2025-12-30 00:25:03.938303 | 2025-12-30 00:25:04.437996 | controller | changed: .d..t...... ./ 2025-12-30 00:25:04.907483 | controller | changed: .d..t...... ./ 2025-12-30 00:25:04.945854 | 2025-12-30 00:25:04.946099 | TASK [include_role : fetch-output-openshift] 2025-12-30 00:25:04.965600 | controller | skipping: Conditional result was False 2025-12-30 00:25:04.977018 | 2025-12-30 00:25:04.977159 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-30 00:25:05.022802 | controller | skipping: Conditional result was False 2025-12-30 00:25:05.038503 | controller | skipping: Conditional result was False 2025-12-30 00:25:05.107390 | 2025-12-30 00:25:05.107518 | PLAY [localhost] 2025-12-30 00:25:05.121030 | 2025-12-30 00:25:05.121138 | TASK [Run Zuul manifest role] 2025-12-30 00:25:05.141928 | localhost | ok 2025-12-30 00:25:05.162670 | 2025-12-30 00:25:05.162840 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-30 00:25:05.594420 | localhost | changed 2025-12-30 00:25:05.599833 | 2025-12-30 00:25:05.599907 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-30 00:25:05.630746 | localhost | ok 2025-12-30 00:25:05.645717 | 2025-12-30 00:25:05.645824 | TASK [Set zuul-log-path fact] 2025-12-30 00:25:05.666557 | localhost | ok 2025-12-30 00:25:05.688850 | 2025-12-30 00:25:05.689020 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-30 00:25:05.722226 | localhost | ok 2025-12-30 00:25:05.736520 | 2025-12-30 00:25:05.736623 | LOOP [Run upload-logs-swift role] 2025-12-30 00:25:05.772484 | localhost | Output suppressed because no_log was given 2025-12-30 00:25:05.807391 | 2025-12-30 00:25:05.807533 | TASK [Set zuul-log-path fact] 2025-12-30 00:25:05.833331 | localhost | skipping: Conditional result was False 2025-12-30 00:25:05.840283 | 2025-12-30 00:25:05.840373 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-30 00:25:06.319070 | localhost -> localhost | ok: Runtime: 0:00:00.005782 2025-12-30 00:25:06.324732 | 2025-12-30 00:25:06.324838 | TASK [upload-logs-swift : Upload logs to swift]