2025-10-25 00:06:36.459929 | Job console starting... 2025-10-25 00:06:36.473379 | Updating repositories 2025-10-25 00:06:37.485189 | Preparing job workspace 2025-10-25 00:06:41.547177 | Running Ansible setup... 2025-10-25 00:06:47.296290 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-25 00:06:47.943128 | 2025-10-25 00:06:47.943283 | PLAY [localhost] 2025-10-25 00:06:47.952384 | 2025-10-25 00:06:47.952492 | TASK [Gathering Facts] 2025-10-25 00:06:49.028622 | localhost | ok 2025-10-25 00:06:49.055005 | 2025-10-25 00:06:49.055116 | TASK [Setup log path fact] 2025-10-25 00:06:49.075505 | localhost | ok 2025-10-25 00:06:49.094386 | 2025-10-25 00:06:49.094485 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-25 00:06:49.137604 | localhost | ok 2025-10-25 00:06:49.148631 | 2025-10-25 00:06:49.148763 | TASK [emit-job-header : Print job information] 2025-10-25 00:06:49.212384 | # Job Information 2025-10-25 00:06:49.212887 | Ansible Version: 2.15.12 2025-10-25 00:06:49.212963 | Job: ansible-test-sanity-docker-devel 2025-10-25 00:06:49.213009 | Pipeline: periodic 2025-10-25 00:06:49.213048 | Executor: ze02.softwarefactory-project.io 2025-10-25 00:06:49.213087 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-25 00:06:49.213293 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/1f8/ansible/1f8f6b53786349e8a05fa4222ec83a31/ 2025-10-25 00:06:49.213333 | Event ID: 475785b7398d4c5089451ad6f27c677f 2025-10-25 00:06:49.222292 | 2025-10-25 00:06:49.222389 | LOOP [emit-job-header : Print node information] 2025-10-25 00:06:49.326688 | localhost | ok: 2025-10-25 00:06:49.326850 | localhost | # Node Information 2025-10-25 00:06:49.326876 | localhost | Inventory Hostname: controller 2025-10-25 00:06:49.326895 | localhost | Hostname: ip-172-16-21-192 2025-10-25 00:06:49.326914 | localhost | Username: zuul-worker 2025-10-25 00:06:49.326935 | localhost | Distro: Fedora 37 2025-10-25 00:06:49.326953 | localhost | Provider: ansible-us-east-2 2025-10-25 00:06:49.326971 | localhost | Region: us-east-2 2025-10-25 00:06:49.326987 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-25 00:06:49.327004 | localhost | Product Name: t3.small 2025-10-25 00:06:49.327020 | localhost | Interface IP: 18.188.13.118 2025-10-25 00:06:49.352898 | 2025-10-25 00:06:49.353188 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-25 00:06:49.778061 | localhost -> localhost | changed 2025-10-25 00:06:49.783491 | 2025-10-25 00:06:49.783556 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-25 00:06:50.806181 | localhost -> localhost | changed 2025-10-25 00:06:50.837583 | 2025-10-25 00:06:50.837724 | PLAY [all:!appliance*] 2025-10-25 00:06:50.857266 | 2025-10-25 00:06:50.857341 | TASK [include_role : start-zuul-console] 2025-10-25 00:06:50.880112 | controller | ok 2025-10-25 00:06:50.894647 | 2025-10-25 00:06:50.894761 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-25 00:06:51.569379 | controller | ok 2025-10-25 00:06:51.593309 | 2025-10-25 00:06:51.593457 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-25 00:06:54.623399 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-25 00:06:54.638733 | 2025-10-25 00:06:54.638906 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-25 00:06:54.798390 | controller | skipping: Conditional result was False 2025-10-25 00:06:54.808256 | 2025-10-25 00:06:54.808357 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-25 00:06:54.834918 | controller | skipping: Conditional result was False 2025-10-25 00:06:54.844031 | 2025-10-25 00:06:54.844127 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-25 00:06:54.870892 | controller | skipping: Conditional result was False 2025-10-25 00:06:54.879959 | 2025-10-25 00:06:54.880050 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-25 00:06:54.905949 | controller | skipping: Conditional result was False 2025-10-25 00:06:54.919966 | 2025-10-25 00:06:54.920090 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-25 00:06:54.949804 | controller | skipping: Conditional result was False 2025-10-25 00:06:54.959397 | 2025-10-25 00:06:54.959502 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-25 00:06:54.985945 | controller | skipping: Conditional result was False 2025-10-25 00:06:55.001478 | 2025-10-25 00:06:55.001573 | TASK [Disable Fedora Modular] 2025-10-25 00:06:55.677771 | controller | changed 2025-10-25 00:06:55.686280 | 2025-10-25 00:06:55.686363 | TASK [Enable EPEL] 2025-10-25 00:06:55.712777 | controller | skipping: Conditional result was False 2025-10-25 00:06:55.726097 | 2025-10-25 00:06:55.726282 | TASK [Register the RHEL node] 2025-10-25 00:06:55.880330 | 2025-10-25 00:06:55.880524 | TASK [Show the subscription-manager status] 2025-10-25 00:06:56.057288 | controller | skipping: Conditional result was False 2025-10-25 00:06:56.064563 | 2025-10-25 00:06:56.064632 | TASK [Enable EPEL on RHEL] 2025-10-25 00:06:56.196063 | controller | skipping: Conditional result was False 2025-10-25 00:06:56.202872 | 2025-10-25 00:06:56.202942 | TASK [Install git and tox] 2025-10-25 00:08:16.241622 | controller | changed 2025-10-25 00:08:16.260384 | 2025-10-25 00:08:16.260585 | TASK [include_role : prepare-workspace] 2025-10-25 00:08:16.297885 | controller | ok 2025-10-25 00:08:16.333709 | 2025-10-25 00:08:16.334205 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-25 00:08:16.815574 | controller | ok 2025-10-25 00:08:16.824919 | 2025-10-25 00:08:16.825053 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-25 00:08:30.172979 | controller | Output suppressed because no_log was given 2025-10-25 00:08:30.182958 | 2025-10-25 00:08:30.183020 | TASK [include_role : prepare-workspace-openshift] 2025-10-25 00:08:30.207191 | controller | skipping: Conditional result was False 2025-10-25 00:08:30.228312 | 2025-10-25 00:08:30.228370 | PLAY [all:!appliance] 2025-10-25 00:08:30.275916 | 2025-10-25 00:08:30.276051 | TASK [Run add-build-sshkey role (RSA)] 2025-10-25 00:08:30.306356 | controller | ok 2025-10-25 00:08:30.322160 | 2025-10-25 00:08:30.322230 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-25 00:08:30.561813 | controller -> localhost | ok 2025-10-25 00:08:30.578259 | 2025-10-25 00:08:30.578407 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-25 00:08:30.610475 | controller | ok 2025-10-25 00:08:30.634994 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-25 00:08:30.644327 | 2025-10-25 00:08:30.644414 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-25 00:08:31.146468 | controller -> localhost | Generating public/private rsa key pair. 2025-10-25 00:08:31.146833 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_rsa. 2025-10-25 00:08:31.146900 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_rsa.pub. 2025-10-25 00:08:31.146946 | controller -> localhost | The key fingerprint is: 2025-10-25 00:08:31.146988 | controller -> localhost | SHA256:phLO+pRtvV3kA/FcMbJQoXNmWcalRJ9+PM2V34ILRns zuul-build-sshkey 2025-10-25 00:08:31.147028 | controller -> localhost | The key's randomart image is: 2025-10-25 00:08:31.147068 | controller -> localhost | +---[RSA 2048]----+ 2025-10-25 00:08:31.147107 | controller -> localhost | | ..++B..| 2025-10-25 00:08:31.147147 | controller -> localhost | | o B.=o| 2025-10-25 00:08:31.147199 | controller -> localhost | | = * ooo| 2025-10-25 00:08:31.147241 | controller -> localhost | | . X o.o=| 2025-10-25 00:08:31.147279 | controller -> localhost | | . S = E .oB| 2025-10-25 00:08:31.147334 | controller -> localhost | | o + + . * . .o| 2025-10-25 00:08:31.147390 | controller -> localhost | | * + . = | 2025-10-25 00:08:31.147446 | controller -> localhost | | o o o . . | 2025-10-25 00:08:31.147488 | controller -> localhost | | ... . . | 2025-10-25 00:08:31.147533 | controller -> localhost | +----[SHA256]-----+ 2025-10-25 00:08:31.147632 | controller -> localhost | ok: Runtime: 0:00:00.105314 2025-10-25 00:08:31.164568 | 2025-10-25 00:08:31.164771 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-25 00:08:31.191748 | controller | ok 2025-10-25 00:08:31.208319 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-25 00:08:31.223584 | 2025-10-25 00:08:31.223704 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-25 00:08:31.249558 | controller | skipping: Conditional result was False 2025-10-25 00:08:31.259333 | 2025-10-25 00:08:31.259441 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-25 00:08:31.894586 | controller | changed 2025-10-25 00:08:31.903024 | 2025-10-25 00:08:31.903112 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-25 00:08:32.247750 | controller | ok 2025-10-25 00:08:32.257521 | 2025-10-25 00:08:32.257605 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-25 00:08:33.620446 | controller | changed 2025-10-25 00:08:33.629337 | 2025-10-25 00:08:33.629429 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-25 00:08:35.463083 | controller | changed 2025-10-25 00:08:35.482985 | 2025-10-25 00:08:35.483165 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-25 00:08:35.512722 | controller | skipping: Conditional result was False 2025-10-25 00:08:35.525079 | 2025-10-25 00:08:35.525219 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-25 00:08:35.968494 | controller -> localhost | changed 2025-10-25 00:08:35.998207 | 2025-10-25 00:08:35.998454 | TASK [add-build-sshkey : Add back temp key] 2025-10-25 00:08:36.315355 | controller -> localhost | Identity added: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_rsa (zuul-build-sshkey) 2025-10-25 00:08:36.315777 | controller -> localhost | ok: Runtime: 0:00:00.012624 2025-10-25 00:08:36.325563 | 2025-10-25 00:08:36.325658 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-25 00:08:36.857337 | controller | ok 2025-10-25 00:08:36.873126 | 2025-10-25 00:08:36.873298 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-25 00:08:36.925964 | controller | skipping: Conditional result was False 2025-10-25 00:08:36.952795 | 2025-10-25 00:08:36.953015 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-25 00:08:36.999353 | controller | ok 2025-10-25 00:08:37.034415 | 2025-10-25 00:08:37.034521 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-25 00:08:37.375923 | controller -> localhost | ok 2025-10-25 00:08:37.389837 | 2025-10-25 00:08:37.389972 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-25 00:08:37.429742 | controller | ok 2025-10-25 00:08:37.453641 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-25 00:08:37.463332 | 2025-10-25 00:08:37.463416 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-25 00:08:37.787953 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-25 00:08:37.788339 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_ecdsa. 2025-10-25 00:08:37.788406 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_ecdsa.pub. 2025-10-25 00:08:37.788469 | controller -> localhost | The key fingerprint is: 2025-10-25 00:08:37.788515 | controller -> localhost | SHA256:QcGea0vU/VPNjnN5I/pA7THsFtfHesJxtfBZiTdYzaw zuul-build-sshkey 2025-10-25 00:08:37.788558 | controller -> localhost | The key's randomart image is: 2025-10-25 00:08:37.788600 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-25 00:08:37.788640 | controller -> localhost | | .o. +.| 2025-10-25 00:08:37.788720 | controller -> localhost | | .. + =| 2025-10-25 00:08:37.788779 | controller -> localhost | | ..o . + *+| 2025-10-25 00:08:37.788823 | controller -> localhost | | +.. + E.@| 2025-10-25 00:08:37.788865 | controller -> localhost | | .S. . B.O*| 2025-10-25 00:08:37.788904 | controller -> localhost | | + . ooX*=| 2025-10-25 00:08:37.788943 | controller -> localhost | | o . ..+=++| 2025-10-25 00:08:37.788982 | controller -> localhost | | . .o o | 2025-10-25 00:08:37.789019 | controller -> localhost | | .. | 2025-10-25 00:08:37.789057 | controller -> localhost | +----[SHA256]-----+ 2025-10-25 00:08:37.789155 | controller -> localhost | ok: Runtime: 0:00:00.014011 2025-10-25 00:08:37.805145 | 2025-10-25 00:08:37.805291 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-25 00:08:37.839697 | controller | ok 2025-10-25 00:08:37.847337 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-25 00:08:37.856515 | 2025-10-25 00:08:37.856576 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-25 00:08:37.882213 | controller | skipping: Conditional result was False 2025-10-25 00:08:37.892889 | 2025-10-25 00:08:37.893014 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-25 00:08:38.346135 | controller | changed 2025-10-25 00:08:38.354207 | 2025-10-25 00:08:38.354297 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-25 00:08:38.700429 | controller | ok 2025-10-25 00:08:38.713792 | 2025-10-25 00:08:38.713937 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-25 00:08:40.315951 | controller | changed 2025-10-25 00:08:40.329609 | 2025-10-25 00:08:40.329793 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-25 00:08:42.273334 | controller | changed 2025-10-25 00:08:42.279363 | 2025-10-25 00:08:42.279428 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-25 00:08:42.303699 | controller | skipping: Conditional result was False 2025-10-25 00:08:42.310754 | 2025-10-25 00:08:42.310838 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-25 00:08:42.548687 | controller -> localhost | changed 2025-10-25 00:08:42.560484 | 2025-10-25 00:08:42.560557 | TASK [add-build-sshkey : Add back temp key] 2025-10-25 00:08:42.896940 | controller -> localhost | Identity added: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/1f8f6b53786349e8a05fa4222ec83a31_id_ecdsa (zuul-build-sshkey) 2025-10-25 00:08:42.897379 | controller -> localhost | ok: Runtime: 0:00:00.014170 2025-10-25 00:08:42.912635 | 2025-10-25 00:08:42.912872 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-25 00:08:43.260515 | controller | ok 2025-10-25 00:08:43.316560 | 2025-10-25 00:08:43.316746 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-25 00:08:43.363268 | controller | skipping: Conditional result was False 2025-10-25 00:08:43.389538 | 2025-10-25 00:08:43.389765 | TASK [include_role : remove-zuul-sshkey] 2025-10-25 00:08:43.416782 | controller | skipping: Conditional result was False 2025-10-25 00:08:43.425741 | 2025-10-25 00:08:43.425844 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-25 00:08:43.817952 | controller | ok: "logs" 2025-10-25 00:08:43.818183 | controller | ok: All items complete 2025-10-25 00:08:43.818211 | 2025-10-25 00:08:44.131063 | controller | ok: "artifacts" 2025-10-25 00:08:44.448567 | controller | ok: "docs" 2025-10-25 00:08:44.473140 | 2025-10-25 00:08:44.473329 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-25 00:08:44.807125 | controller | changed: "logs" 2025-10-25 00:08:45.092656 | controller | changed: "artifacts" 2025-10-25 00:08:45.377418 | controller | changed: "docs" 2025-10-25 00:08:45.449912 | 2025-10-25 00:08:45.450085 | PLAY RECAP 2025-10-25 00:08:45.450170 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-25 00:08:45.450225 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-25 00:08:45.450264 | 2025-10-25 00:08:45.588943 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-25 00:08:45.591025 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-25 00:08:46.231055 | 2025-10-25 00:08:46.231180 | PLAY [all] 2025-10-25 00:08:46.257419 | 2025-10-25 00:08:46.257551 | TASK [Install binary dependencies] 2025-10-25 00:08:46.298206 | controller | ok 2025-10-25 00:08:46.320164 | 2025-10-25 00:08:46.320259 | TASK [bindep : Include find tasks] 2025-10-25 00:08:46.350791 | controller | ok 2025-10-25 00:08:46.358936 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-25 00:08:46.364952 | 2025-10-25 00:08:46.365014 | TASK [bindep : Look for bindep.txt] 2025-10-25 00:08:46.890808 | controller | ok 2025-10-25 00:08:46.905557 | 2025-10-25 00:08:46.905740 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:08:46.933170 | controller | skipping: Conditional result was False 2025-10-25 00:08:46.946312 | 2025-10-25 00:08:46.946453 | TASK [bindep : Look for other-requirements.txt] 2025-10-25 00:08:47.269638 | controller | ok 2025-10-25 00:08:47.281447 | 2025-10-25 00:08:47.281593 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:08:47.318545 | controller | skipping: Conditional result was False 2025-10-25 00:08:47.332973 | 2025-10-25 00:08:47.333126 | TASK [bindep : Look for bindep fallback file] 2025-10-25 00:08:47.370894 | controller | skipping: Conditional result was False 2025-10-25 00:08:47.383648 | 2025-10-25 00:08:47.383822 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:08:47.421039 | controller | skipping: Conditional result was False 2025-10-25 00:08:47.436255 | 2025-10-25 00:08:47.436401 | TASK [bindep : Include bindep tasks] 2025-10-25 00:08:47.474605 | controller | skipping: Conditional result was False 2025-10-25 00:08:47.491918 | 2025-10-25 00:08:47.492059 | TASK [bindep : Include install tasks] 2025-10-25 00:08:47.529597 | controller | skipping: Conditional result was False 2025-10-25 00:08:47.544044 | 2025-10-25 00:08:47.544188 | LOOP [bindep : Include package tasks] 2025-10-25 00:08:47.639050 | 2025-10-25 00:08:47.639367 | TASK [Run test-setup role] 2025-10-25 00:08:47.668812 | controller | ok 2025-10-25 00:08:47.713196 | 2025-10-25 00:08:47.713363 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-25 00:08:48.048613 | controller | ok 2025-10-25 00:08:48.062468 | 2025-10-25 00:08:48.062606 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-25 00:08:48.221166 | controller | skipping: Conditional result was False 2025-10-25 00:08:48.271858 | 2025-10-25 00:08:48.271940 | PLAY RECAP 2025-10-25 00:08:48.271995 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-25 00:08:48.272022 | 2025-10-25 00:08:48.390075 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-25 00:08:48.391500 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-25 00:08:49.037836 | 2025-10-25 00:08:49.037967 | PLAY [controller] 2025-10-25 00:08:49.058029 | 2025-10-25 00:08:49.058157 | TASK [Create the /root directory] 2025-10-25 00:08:49.699045 | controller | ok 2025-10-25 00:08:49.711573 | 2025-10-25 00:08:49.711771 | TASK [Install glibc-langpack-en] 2025-10-25 00:08:57.431368 | controller | ok: Nothing to do 2025-10-25 00:08:57.444901 | 2025-10-25 00:08:57.445041 | TASK [Ensure controller directory exists] 2025-10-25 00:08:57.970822 | controller | changed 2025-10-25 00:08:57.984797 | 2025-10-25 00:08:57.984959 | TASK [Install container runtime] 2025-10-25 00:08:58.056533 | controller | ok 2025-10-25 00:08:58.111771 | 2025-10-25 00:08:58.111929 | LOOP [ensure-podman : Find distribution installation] 2025-10-25 00:08:58.140033 | controller | ok: "/var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-25 00:08:58.167414 | controller | included: /var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-25 00:08:58.183708 | 2025-10-25 00:08:58.183875 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-25 00:10:08.955306 | controller | changed 2025-10-25 00:10:08.969745 | 2025-10-25 00:10:08.969887 | TASK [ensure-podman : Fetch podman version] 2025-10-25 00:10:09.694727 | controller | Client: Podman Engine 2025-10-25 00:10:09.694804 | controller | Version: 4.6.2 2025-10-25 00:10:09.694834 | controller | API Version: 4.6.2 2025-10-25 00:10:09.694861 | controller | Go Version: go1.19.12 2025-10-25 00:10:09.694900 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-25 00:10:09.694929 | controller | OS/Arch: linux/amd64 2025-10-25 00:10:10.130075 | controller | ok: Runtime: 0:00:00.192064 2025-10-25 00:10:10.144280 | 2025-10-25 00:10:10.144655 | TASK [ensure-podman : Print podman version installed] 2025-10-25 00:10:10.183998 | Podman version: Client: Podman Engine 2025-10-25 00:10:10.184265 | Version: 4.6.2 2025-10-25 00:10:10.184329 | API Version: 4.6.2 2025-10-25 00:10:10.184376 | Go Version: go1.19.12 2025-10-25 00:10:10.184418 | Built: Mon Aug 28 19:38:31 2023 2025-10-25 00:10:10.184465 | OS/Arch: linux/amd64 2025-10-25 00:10:10.196653 | 2025-10-25 00:10:10.196817 | TASK [ensure-podman : Validate podman engine] 2025-10-25 00:10:10.342978 | controller | skipping: Conditional result was False 2025-10-25 00:10:10.352176 | 2025-10-25 00:10:10.352312 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-25 00:10:10.377358 | controller | skipping: Conditional result was False 2025-10-25 00:10:10.392221 | 2025-10-25 00:10:10.392328 | TASK [Ensure python3.8 is present] 2025-10-25 00:10:10.416912 | controller | skipping: Conditional result was False 2025-10-25 00:10:10.424827 | 2025-10-25 00:10:10.424921 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-25 00:10:10.454279 | controller | ok 2025-10-25 00:10:10.481563 | 2025-10-25 00:10:10.481705 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-25 00:10:13.937926 | controller | ok: Nothing to do 2025-10-25 00:10:13.951375 | 2025-10-25 00:10:13.951509 | TASK [our-ensure-python : Also install python3-devel] 2025-10-25 00:10:26.586721 | controller | changed 2025-10-25 00:10:26.607445 | 2025-10-25 00:10:26.607573 | TASK [Run ensure-virtualenv role] 2025-10-25 00:10:26.639283 | controller | ok 2025-10-25 00:10:26.669840 | 2025-10-25 00:10:26.669937 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-25 00:10:27.045281 | controller | /usr/bin/virtualenv 2025-10-25 00:10:27.313473 | controller | ok: Runtime: 0:00:00.003719 2025-10-25 00:10:27.327169 | 2025-10-25 00:10:27.327324 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-25 00:10:27.363372 | controller | skipping: Conditional result was False 2025-10-25 00:10:27.363693 | controller | ok: All items complete 2025-10-25 00:10:27.363724 | 2025-10-25 00:10:27.389089 | 2025-10-25 00:10:27.389288 | TASK [Find the full path of the Python interpreter] 2025-10-25 00:10:27.754664 | controller | /usr/bin/python3 2025-10-25 00:10:28.083268 | controller | ok 2025-10-25 00:10:28.097591 | 2025-10-25 00:10:28.097819 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-25 00:10:29.618170 | controller | created virtual environment CPython3.11.0.final.0-64 in 771ms 2025-10-25 00:10:29.655783 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-25 00:10:29.655836 | 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-worker/.local/share/virtualenv) 2025-10-25 00:10:29.655855 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-25 00:10:29.655877 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-25 00:10:29.775269 | controller | changed 2025-10-25 00:10:29.788822 | 2025-10-25 00:10:29.788964 | TASK [Set selinux package] 2025-10-25 00:10:29.819811 | controller | ok 2025-10-25 00:10:29.833293 | 2025-10-25 00:10:29.833435 | TASK [Set selinux package (Fedora)] 2025-10-25 00:10:29.869226 | controller | ok 2025-10-25 00:10:29.877486 | 2025-10-25 00:10:29.877589 | TASK [Install selinux into virtualenv] 2025-10-25 00:10:32.400127 | controller | Collecting selinux-please-lie-to-me 2025-10-25 00:10:32.496284 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-25 00:10:33.031836 | controller | Collecting setuptools<50.0.0 2025-10-25 00:10:33.044642 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-25 00:10:33.166846 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-10-25 00:10:33.316033 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-25 00:10:33.316354 | controller | Attempting uninstall: setuptools 2025-10-25 00:10:33.321127 | controller | Found existing installation: setuptools 62.6.0 2025-10-25 00:10:33.429731 | controller | Uninstalling setuptools-62.6.0: 2025-10-25 00:10:33.444361 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-25 00:10:34.158719 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-25 00:10:34.364770 | controller | 2025-10-25 00:10:34.580524 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-25 00:10:34.580569 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-25 00:10:35.063956 | controller | ok: Runtime: 0:00:04.208963 2025-10-25 00:10:35.078030 | 2025-10-25 00:10:35.078220 | TASK [Install pytest-forked into virtualenv] 2025-10-25 00:10:36.287532 | controller | Collecting pytest-forked 2025-10-25 00:10:36.371816 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-25 00:10:36.432428 | controller | Collecting py 2025-10-25 00:10:36.444724 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-25 00:10:36.481706 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00 2025-10-25 00:10:36.652248 | controller | Collecting pytest>=3.10 2025-10-25 00:10:36.665398 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-25 00:10:36.727283 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-10-25 00:10:36.784418 | controller | Collecting iniconfig>=1 2025-10-25 00:10:36.800189 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-25 00:10:36.866411 | controller | Collecting packaging>=20 2025-10-25 00:10:36.878160 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-25 00:10:36.890515 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.5 MB/s eta 0:00:00 2025-10-25 00:10:36.936517 | controller | Collecting pluggy<2,>=1.5 2025-10-25 00:10:36.948321 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-25 00:10:37.020778 | controller | Collecting pygments>=2.7.2 2025-10-25 00:10:37.033215 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-25 00:10:37.148594 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.9 MB/s eta 0:00:00 2025-10-25 00:10:37.279678 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-25 00:10:39.406700 | controller | Successfully installed iniconfig-2.3.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-25 00:10:39.425544 | controller | 2025-10-25 00:10:39.572719 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-25 00:10:39.572770 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-25 00:10:39.763451 | controller | ok: Runtime: 0:00:03.999945 2025-10-25 00:10:39.770247 | 2025-10-25 00:10:39.770325 | TASK [Update pip] 2025-10-25 00:10:40.843251 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-25 00:10:41.123449 | controller | Collecting pip 2025-10-25 00:10:41.220494 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-25 00:10:41.417055 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.1 MB/s eta 0:00:00 2025-10-25 00:10:41.559401 | controller | Installing collected packages: pip 2025-10-25 00:10:41.559800 | controller | Attempting uninstall: pip 2025-10-25 00:10:41.564036 | controller | Found existing installation: pip 22.2.2 2025-10-25 00:10:41.813454 | controller | Uninstalling pip-22.2.2: 2025-10-25 00:10:41.841897 | controller | Successfully uninstalled pip-22.2.2 2025-10-25 00:10:43.508863 | controller | Successfully installed pip-25.2 2025-10-25 00:10:43.902028 | controller | ok: Runtime: 0:00:03.380009 2025-10-25 00:10:43.915859 | 2025-10-25 00:10:43.916006 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-25 00:10:44.449149 | controller | changed 2025-10-25 00:10:44.460890 | 2025-10-25 00:10:44.461100 | TASK [Install ansible into virtualenv] 2025-10-25 00:10:45.493426 | controller | Processing ./src/github.com/ansible/ansible 2025-10-25 00:10:45.499450 | controller | Installing build dependencies: started 2025-10-25 00:10:47.186056 | controller | Installing build dependencies: finished with status 'done' 2025-10-25 00:10:48.632048 | controller | Getting requirements to build wheel: started 2025-10-25 00:10:48.632113 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-25 00:10:48.633181 | controller | Preparing metadata (pyproject.toml): started 2025-10-25 00:10:49.513058 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-25 00:10:49.515864 | 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-25 00:10:49.520605 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-25 00:10:50.117421 | controller | ERROR 2025-10-25 00:10:50.117778 | controller | { 2025-10-25 00:10:50.117855 | controller | "delta": "0:00:04.748615", 2025-10-25 00:10:50.117900 | controller | "end": "2025-10-25 00:10:49.648126", 2025-10-25 00:10:50.117938 | controller | "msg": "non-zero return code", 2025-10-25 00:10:50.117990 | controller | "rc": 1, 2025-10-25 00:10:50.118029 | controller | "start": "2025-10-25 00:10:44.899511" 2025-10-25 00:10:50.118064 | controller | } failure 2025-10-25 00:10:50.120826 | 2025-10-25 00:10:50.120925 | PLAY RECAP 2025-10-25 00:10:50.121012 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-25 00:10:50.121055 | 2025-10-25 00:10:50.254320 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-25 00:10:50.256192 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-25 00:10:50.834873 | 2025-10-25 00:10:50.834987 | PLAY [all] 2025-10-25 00:10:50.855932 | 2025-10-25 00:10:50.856018 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-25 00:10:51.703640 | controller | changed: non-zero return code 2025-10-25 00:10:51.711153 | 2025-10-25 00:10:51.711277 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-25 00:10:51.736791 | controller | skipping: Conditional result was False 2025-10-25 00:10:51.749092 | 2025-10-25 00:10:51.749244 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-25 00:10:51.789047 | 2025-10-25 00:10:51.789284 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-25 00:10:51.828527 | 2025-10-25 00:10:51.828811 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-25 00:10:51.855904 | controller | skipping: Conditional result was False 2025-10-25 00:10:51.868852 | 2025-10-25 00:10:51.868998 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-25 00:10:51.909801 | 2025-10-25 00:10:51.910036 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-25 00:10:51.937068 | controller | skipping: Conditional result was False 2025-10-25 00:10:51.950024 | 2025-10-25 00:10:51.950168 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-25 00:10:51.977244 | controller | skipping: Conditional result was False 2025-10-25 00:10:51.989430 | 2025-10-25 00:10:51.989583 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-25 00:10:52.017445 | controller | skipping: Conditional result was False 2025-10-25 00:10:52.060183 | 2025-10-25 00:10:52.060262 | PLAY RECAP 2025-10-25 00:10:52.060317 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-25 00:10:52.060344 | 2025-10-25 00:10:52.160244 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-25 00:10:52.161938 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-25 00:10:52.799190 | 2025-10-25 00:10:52.799313 | PLAY [all:!appliance*] 2025-10-25 00:10:52.839273 | 2025-10-25 00:10:52.839465 | TASK [unregister the node] 2025-10-25 00:10:52.971913 | controller | skipping: Conditional result was False 2025-10-25 00:10:52.984610 | 2025-10-25 00:10:52.984859 | TASK [include_role : fetch-output] 2025-10-25 00:10:53.029683 | controller | ok 2025-10-25 00:10:53.068169 | 2025-10-25 00:10:53.068316 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-25 00:10:53.143825 | controller | skipping: Conditional result was False 2025-10-25 00:10:53.150068 | 2025-10-25 00:10:53.150173 | TASK [fetch-output : Set log path for single node] 2025-10-25 00:10:53.183149 | controller | ok 2025-10-25 00:10:53.188278 | 2025-10-25 00:10:53.188347 | LOOP [fetch-output : Ensure local output dirs] 2025-10-25 00:10:53.592175 | controller -> localhost | ok: "/var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/logs" 2025-10-25 00:10:53.843573 | controller -> localhost | changed: "/var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/artifacts" 2025-10-25 00:10:54.078549 | controller -> localhost | changed: "/var/lib/zuul/builds/1f8f6b53786349e8a05fa4222ec83a31/work/docs" 2025-10-25 00:10:54.088952 | 2025-10-25 00:10:54.089067 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-25 00:10:55.370367 | controller | changed: 2025-10-25 00:10:55.370788 | controller | .d..t...... ./ 2025-10-25 00:10:55.370889 | controller | cd+++++++++ controller/ 2025-10-25 00:10:55.371026 | controller | changed: All items complete 2025-10-25 00:10:55.371101 | 2025-10-25 00:10:56.475825 | controller | changed: .d..t...... ./ 2025-10-25 00:10:57.488955 | controller | changed: .d..t...... ./ 2025-10-25 00:10:57.513702 | 2025-10-25 00:10:57.513910 | TASK [include_role : fetch-output-openshift] 2025-10-25 00:10:57.540705 | controller | skipping: Conditional result was False 2025-10-25 00:10:57.557932 | 2025-10-25 00:10:57.558235 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-25 00:10:57.606099 | controller | skipping: Conditional result was False 2025-10-25 00:10:57.617898 | controller | skipping: Conditional result was False 2025-10-25 00:10:57.665520 | 2025-10-25 00:10:57.665657 | PLAY [localhost] 2025-10-25 00:10:57.683738 | 2025-10-25 00:10:57.683855 | TASK [Run Zuul manifest role] 2025-10-25 00:10:57.706284 | localhost | ok 2025-10-25 00:10:57.725415 | 2025-10-25 00:10:57.725516 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-25 00:10:58.106935 | localhost | changed 2025-10-25 00:10:58.118215 | 2025-10-25 00:10:58.118362 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-25 00:10:58.176256 | localhost | ok 2025-10-25 00:10:58.195018 | 2025-10-25 00:10:58.195146 | TASK [Set zuul-log-path fact] 2025-10-25 00:10:58.222470 | localhost | ok 2025-10-25 00:10:58.252131 | 2025-10-25 00:10:58.252275 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-25 00:10:58.297864 | localhost | ok 2025-10-25 00:10:58.307453 | 2025-10-25 00:10:58.307521 | LOOP [Run upload-logs-swift role] 2025-10-25 00:10:58.341485 | localhost | Output suppressed because no_log was given 2025-10-25 00:10:58.367156 | 2025-10-25 00:10:58.367228 | TASK [Set zuul-log-path fact] 2025-10-25 00:10:58.391452 | localhost | skipping: Conditional result was False 2025-10-25 00:10:58.399143 | 2025-10-25 00:10:58.399284 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-25 00:10:58.891039 | localhost -> localhost | ok: Runtime: 0:00:00.015440 2025-10-25 00:10:58.896442 | 2025-10-25 00:10:58.896505 | TASK [upload-logs-swift : Upload logs to swift]