2025-10-06 00:06:35.207560 | Job console starting... 2025-10-06 00:06:35.224989 | Updating repositories 2025-10-06 00:06:35.356220 | Preparing job workspace 2025-10-06 00:06:39.278217 | Running Ansible setup... 2025-10-06 00:06:45.529451 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-06 00:06:46.231074 | 2025-10-06 00:06:46.231220 | PLAY [localhost] 2025-10-06 00:06:46.242134 | 2025-10-06 00:06:46.242271 | TASK [Gathering Facts] 2025-10-06 00:06:47.181024 | localhost | ok 2025-10-06 00:06:47.201595 | 2025-10-06 00:06:47.201776 | TASK [Setup log path fact] 2025-10-06 00:06:47.234512 | localhost | ok 2025-10-06 00:06:47.254944 | 2025-10-06 00:06:47.255062 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-06 00:06:47.295087 | localhost | ok 2025-10-06 00:06:47.308168 | 2025-10-06 00:06:47.308301 | TASK [emit-job-header : Print job information] 2025-10-06 00:06:47.358892 | # Job Information 2025-10-06 00:06:47.359062 | Ansible Version: 2.15.12 2025-10-06 00:06:47.359094 | Job: ansible-test-sanity-docker-devel 2025-10-06 00:06:47.359115 | Pipeline: periodic 2025-10-06 00:06:47.359134 | Executor: ze03.softwarefactory-project.io 2025-10-06 00:06:47.359152 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-06 00:06:47.359173 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d51/ansible/d51388694ef548df951a68b59a515b34/ 2025-10-06 00:06:47.359194 | Event ID: 9d310e2ddb83445ab53d82797698fe1c 2025-10-06 00:06:47.362928 | 2025-10-06 00:06:47.362995 | LOOP [emit-job-header : Print node information] 2025-10-06 00:06:47.498087 | localhost | ok: 2025-10-06 00:06:47.498342 | localhost | # Node Information 2025-10-06 00:06:47.498377 | localhost | Inventory Hostname: controller 2025-10-06 00:06:47.498405 | localhost | Hostname: ip-172-16-86-78 2025-10-06 00:06:47.498430 | localhost | Username: zuul-worker 2025-10-06 00:06:47.498458 | localhost | Distro: Fedora 37 2025-10-06 00:06:47.498484 | localhost | Provider: ansible-us-east-2 2025-10-06 00:06:47.498509 | localhost | Region: us-east-2 2025-10-06 00:06:47.498537 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-06 00:06:47.498564 | localhost | Product Name: t3.small 2025-10-06 00:06:47.498590 | localhost | Interface IP: 13.59.204.127 2025-10-06 00:06:47.516885 | 2025-10-06 00:06:47.517138 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-06 00:06:48.067700 | localhost -> localhost | changed 2025-10-06 00:06:48.080099 | 2025-10-06 00:06:48.080244 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-06 00:06:49.098013 | localhost -> localhost | changed 2025-10-06 00:06:49.118085 | 2025-10-06 00:06:49.118150 | PLAY [all:!appliance*] 2025-10-06 00:06:49.133258 | 2025-10-06 00:06:49.133325 | TASK [include_role : start-zuul-console] 2025-10-06 00:06:49.161852 | controller | ok 2025-10-06 00:06:49.176789 | 2025-10-06 00:06:49.176877 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-06 00:06:49.873337 | controller | ok 2025-10-06 00:06:49.892245 | 2025-10-06 00:06:49.892396 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-06 00:06:51.962459 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-06 00:06:51.976410 | 2025-10-06 00:06:51.976614 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-06 00:06:52.138421 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.147157 | 2025-10-06 00:06:52.147311 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-06 00:06:52.175445 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.188115 | 2025-10-06 00:06:52.188285 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-06 00:06:52.215580 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.225385 | 2025-10-06 00:06:52.225512 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-06 00:06:52.251711 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.260523 | 2025-10-06 00:06:52.260643 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-06 00:06:52.275088 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.283513 | 2025-10-06 00:06:52.283635 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-06 00:06:52.297919 | controller | skipping: Conditional result was False 2025-10-06 00:06:52.312801 | 2025-10-06 00:06:52.312932 | TASK [Disable Fedora Modular] 2025-10-06 00:06:52.976491 | controller | changed 2025-10-06 00:06:52.994398 | 2025-10-06 00:06:52.994632 | TASK [Enable EPEL] 2025-10-06 00:06:53.014078 | controller | skipping: Conditional result was False 2025-10-06 00:06:53.025439 | 2025-10-06 00:06:53.025601 | TASK [Register the RHEL node] 2025-10-06 00:06:53.193248 | 2025-10-06 00:06:53.193518 | TASK [Show the subscription-manager status] 2025-10-06 00:06:53.436161 | controller | skipping: Conditional result was False 2025-10-06 00:06:53.448601 | 2025-10-06 00:06:53.448810 | TASK [Enable EPEL on RHEL] 2025-10-06 00:06:53.611357 | controller | skipping: Conditional result was False 2025-10-06 00:06:53.624512 | 2025-10-06 00:06:53.624702 | TASK [Install git and tox] 2025-10-06 00:08:23.468696 | controller | changed 2025-10-06 00:08:23.482126 | 2025-10-06 00:08:23.482265 | TASK [include_role : prepare-workspace] 2025-10-06 00:08:23.520885 | controller | ok 2025-10-06 00:08:23.555472 | 2025-10-06 00:08:23.555574 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-06 00:08:24.082222 | controller | ok 2025-10-06 00:08:24.095323 | 2025-10-06 00:08:24.095493 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-06 00:08:39.688616 | controller | Output suppressed because no_log was given 2025-10-06 00:08:39.740571 | 2025-10-06 00:08:39.740680 | TASK [include_role : prepare-workspace-openshift] 2025-10-06 00:08:39.758773 | controller | skipping: Conditional result was False 2025-10-06 00:08:39.781293 | 2025-10-06 00:08:39.781377 | PLAY [all:!appliance] 2025-10-06 00:08:39.812295 | 2025-10-06 00:08:39.812402 | TASK [Run add-build-sshkey role (RSA)] 2025-10-06 00:08:39.831918 | controller | ok 2025-10-06 00:08:39.845858 | 2025-10-06 00:08:39.845947 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-06 00:08:40.083538 | controller -> localhost | ok 2025-10-06 00:08:40.092936 | 2025-10-06 00:08:40.093039 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-06 00:08:40.129875 | controller | ok 2025-10-06 00:08:40.150458 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-06 00:08:40.158652 | 2025-10-06 00:08:40.158760 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-06 00:08:40.704900 | controller -> localhost | Generating public/private rsa key pair. 2025-10-06 00:08:40.705165 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_rsa. 2025-10-06 00:08:40.705206 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_rsa.pub. 2025-10-06 00:08:40.705236 | controller -> localhost | The key fingerprint is: 2025-10-06 00:08:40.705264 | controller -> localhost | SHA256:hxVKmapRKXv8OJMGwNYb9aGlwkmdF2HuJoE0YSCV6RM zuul-build-sshkey 2025-10-06 00:08:40.705292 | controller -> localhost | The key's randomart image is: 2025-10-06 00:08:40.705318 | controller -> localhost | +---[RSA 2048]----+ 2025-10-06 00:08:40.705345 | controller -> localhost | |.oo=*+.oB=. | 2025-10-06 00:08:40.705372 | controller -> localhost | | .E=++=O+o . | 2025-10-06 00:08:40.705397 | controller -> localhost | | o o=B+o+ . | 2025-10-06 00:08:40.705423 | controller -> localhost | | o =.+o o | 2025-10-06 00:08:40.705449 | controller -> localhost | | . =.+S . | 2025-10-06 00:08:40.705486 | controller -> localhost | | . *o.. | 2025-10-06 00:08:40.705521 | controller -> localhost | | . o | 2025-10-06 00:08:40.705549 | controller -> localhost | | | 2025-10-06 00:08:40.705576 | controller -> localhost | | | 2025-10-06 00:08:40.705606 | controller -> localhost | +----[SHA256]-----+ 2025-10-06 00:08:40.705677 | controller -> localhost | ok: Runtime: 0:00:00.094420 2025-10-06 00:08:40.718678 | 2025-10-06 00:08:40.718787 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-06 00:08:40.740274 | controller | ok 2025-10-06 00:08:40.755801 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-06 00:08:40.764908 | 2025-10-06 00:08:40.765005 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-06 00:08:40.788683 | controller | skipping: Conditional result was False 2025-10-06 00:08:40.795577 | 2025-10-06 00:08:40.795676 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-06 00:08:41.415586 | controller | changed 2025-10-06 00:08:41.428682 | 2025-10-06 00:08:41.428923 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-06 00:08:41.781434 | controller | ok 2025-10-06 00:08:41.797086 | 2025-10-06 00:08:41.797282 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-06 00:08:43.077209 | controller | changed 2025-10-06 00:08:43.085327 | 2025-10-06 00:08:43.085451 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-06 00:08:44.394785 | controller | changed 2025-10-06 00:08:44.403152 | 2025-10-06 00:08:44.403247 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-06 00:08:44.430102 | controller | skipping: Conditional result was False 2025-10-06 00:08:44.440319 | 2025-10-06 00:08:44.440433 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-06 00:08:44.842189 | controller -> localhost | changed 2025-10-06 00:08:44.855430 | 2025-10-06 00:08:44.855551 | TASK [add-build-sshkey : Add back temp key] 2025-10-06 00:08:45.165806 | controller -> localhost | Identity added: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_rsa (zuul-build-sshkey) 2025-10-06 00:08:45.166039 | controller -> localhost | ok: Runtime: 0:00:00.024714 2025-10-06 00:08:45.174156 | 2025-10-06 00:08:45.174251 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-06 00:08:45.699498 | controller | ok 2025-10-06 00:08:45.719389 | 2025-10-06 00:08:45.719509 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-06 00:08:45.755523 | controller | skipping: Conditional result was False 2025-10-06 00:08:45.768353 | 2025-10-06 00:08:45.768455 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-06 00:08:45.799294 | controller | ok 2025-10-06 00:08:45.822078 | 2025-10-06 00:08:45.822211 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-06 00:08:46.039248 | controller -> localhost | ok 2025-10-06 00:08:46.046091 | 2025-10-06 00:08:46.046168 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-06 00:08:46.076708 | controller | ok 2025-10-06 00:08:46.088980 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-06 00:08:46.097182 | 2025-10-06 00:08:46.097283 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-06 00:08:46.386048 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-06 00:08:46.386259 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_ecdsa. 2025-10-06 00:08:46.386290 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_ecdsa.pub. 2025-10-06 00:08:46.386322 | controller -> localhost | The key fingerprint is: 2025-10-06 00:08:46.386345 | controller -> localhost | SHA256:SMyDyhWbHjUypL6ZxGDwfR4fYn+WZNxWXH8ApapyRc8 zuul-build-sshkey 2025-10-06 00:08:46.386367 | controller -> localhost | The key's randomart image is: 2025-10-06 00:08:46.386388 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-06 00:08:46.386409 | controller -> localhost | |. .= o .++..| 2025-10-06 00:08:46.386429 | controller -> localhost | |.. o @ . . . o...| 2025-10-06 00:08:46.386449 | controller -> localhost | |..o B X . = + o| 2025-10-06 00:08:46.386469 | controller -> localhost | |.= + * B = * .| 2025-10-06 00:08:46.386490 | controller -> localhost | | * . o S * E | 2025-10-06 00:08:46.386511 | controller -> localhost | | . + = | 2025-10-06 00:08:46.386531 | controller -> localhost | | + . o | 2025-10-06 00:08:46.386551 | controller -> localhost | | o | 2025-10-06 00:08:46.386571 | controller -> localhost | | | 2025-10-06 00:08:46.386591 | controller -> localhost | +----[SHA256]-----+ 2025-10-06 00:08:46.386647 | controller -> localhost | ok: Runtime: 0:00:00.007959 2025-10-06 00:08:46.395401 | 2025-10-06 00:08:46.395503 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-06 00:08:46.416087 | controller | ok 2025-10-06 00:08:46.423567 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-06 00:08:46.432971 | 2025-10-06 00:08:46.433040 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-06 00:08:46.448623 | controller | skipping: Conditional result was False 2025-10-06 00:08:46.455969 | 2025-10-06 00:08:46.456041 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-06 00:08:46.902210 | controller | changed 2025-10-06 00:08:46.917303 | 2025-10-06 00:08:46.917448 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-06 00:08:47.410500 | controller | ok 2025-10-06 00:08:47.418032 | 2025-10-06 00:08:47.418124 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-06 00:08:48.971902 | controller | changed 2025-10-06 00:08:48.983585 | 2025-10-06 00:08:48.983680 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-06 00:08:50.490394 | controller | changed 2025-10-06 00:08:50.503079 | 2025-10-06 00:08:50.503251 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-06 00:08:50.541335 | controller | skipping: Conditional result was False 2025-10-06 00:08:50.558262 | 2025-10-06 00:08:50.558469 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-06 00:08:50.862985 | controller -> localhost | changed 2025-10-06 00:08:50.874086 | 2025-10-06 00:08:50.874178 | TASK [add-build-sshkey : Add back temp key] 2025-10-06 00:08:51.124146 | controller -> localhost | Identity added: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/d51388694ef548df951a68b59a515b34_id_ecdsa (zuul-build-sshkey) 2025-10-06 00:08:51.124367 | controller -> localhost | ok: Runtime: 0:00:00.007207 2025-10-06 00:08:51.133572 | 2025-10-06 00:08:51.133636 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-06 00:08:51.438861 | controller | ok 2025-10-06 00:08:51.450106 | 2025-10-06 00:08:51.450238 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-06 00:08:51.473455 | controller | skipping: Conditional result was False 2025-10-06 00:08:51.485088 | 2025-10-06 00:08:51.485175 | TASK [include_role : remove-zuul-sshkey] 2025-10-06 00:08:51.498321 | controller | skipping: Conditional result was False 2025-10-06 00:08:51.505616 | 2025-10-06 00:08:51.505697 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-06 00:08:51.823380 | controller | ok: "logs" 2025-10-06 00:08:51.823827 | controller | ok: All items complete 2025-10-06 00:08:51.823896 | 2025-10-06 00:08:52.081780 | controller | ok: "artifacts" 2025-10-06 00:08:52.351293 | controller | ok: "docs" 2025-10-06 00:08:52.358497 | 2025-10-06 00:08:52.358566 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-06 00:08:52.666119 | controller | changed: "logs" 2025-10-06 00:08:52.938344 | controller | changed: "artifacts" 2025-10-06 00:08:53.243249 | controller | changed: "docs" 2025-10-06 00:08:53.290650 | 2025-10-06 00:08:53.290810 | PLAY RECAP 2025-10-06 00:08:53.290908 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-06 00:08:53.290984 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-06 00:08:53.291047 | 2025-10-06 00:08:53.408589 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-06 00:08:53.410313 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-06 00:08:53.991121 | 2025-10-06 00:08:53.991430 | PLAY [all] 2025-10-06 00:08:54.018567 | 2025-10-06 00:08:54.018748 | TASK [Install binary dependencies] 2025-10-06 00:08:54.070371 | controller | ok 2025-10-06 00:08:54.092672 | 2025-10-06 00:08:54.092840 | TASK [bindep : Include find tasks] 2025-10-06 00:08:54.122554 | controller | ok 2025-10-06 00:08:54.130752 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-06 00:08:54.137365 | 2025-10-06 00:08:54.137462 | TASK [bindep : Look for bindep.txt] 2025-10-06 00:08:54.656795 | controller | ok 2025-10-06 00:08:54.669140 | 2025-10-06 00:08:54.669264 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:08:54.694490 | controller | skipping: Conditional result was False 2025-10-06 00:08:54.703667 | 2025-10-06 00:08:54.703829 | TASK [bindep : Look for other-requirements.txt] 2025-10-06 00:08:55.002869 | controller | ok 2025-10-06 00:08:55.010240 | 2025-10-06 00:08:55.010339 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:08:55.046031 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.065373 | 2025-10-06 00:08:55.065538 | TASK [bindep : Look for bindep fallback file] 2025-10-06 00:08:55.113812 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.129413 | 2025-10-06 00:08:55.129633 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:08:55.188535 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.196966 | 2025-10-06 00:08:55.197064 | TASK [bindep : Include bindep tasks] 2025-10-06 00:08:55.222404 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.233516 | 2025-10-06 00:08:55.233609 | TASK [bindep : Include install tasks] 2025-10-06 00:08:55.259613 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.268300 | 2025-10-06 00:08:55.268402 | LOOP [bindep : Include package tasks] 2025-10-06 00:08:55.324115 | 2025-10-06 00:08:55.324272 | TASK [Run test-setup role] 2025-10-06 00:08:55.342800 | controller | ok 2025-10-06 00:08:55.362603 | 2025-10-06 00:08:55.362758 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-06 00:08:55.648399 | controller | ok 2025-10-06 00:08:55.654763 | 2025-10-06 00:08:55.654829 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-06 00:08:55.794909 | controller | skipping: Conditional result was False 2025-10-06 00:08:55.845841 | 2025-10-06 00:08:55.845954 | PLAY RECAP 2025-10-06 00:08:55.846007 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-06 00:08:55.846035 | 2025-10-06 00:08:55.951893 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-06 00:08:55.953613 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-06 00:08:56.544610 | 2025-10-06 00:08:56.544748 | PLAY [controller] 2025-10-06 00:08:56.574859 | 2025-10-06 00:08:56.574938 | TASK [Create the /root directory] 2025-10-06 00:08:57.145100 | controller | ok 2025-10-06 00:08:57.157638 | 2025-10-06 00:08:57.157844 | TASK [Install glibc-langpack-en] 2025-10-06 00:09:05.362840 | controller | ok: Nothing to do 2025-10-06 00:09:05.374936 | 2025-10-06 00:09:05.375269 | TASK [Ensure controller directory exists] 2025-10-06 00:09:05.866562 | controller | changed 2025-10-06 00:09:05.879118 | 2025-10-06 00:09:05.879300 | TASK [Install container runtime] 2025-10-06 00:09:05.960242 | controller | ok 2025-10-06 00:09:06.024064 | 2025-10-06 00:09:06.024225 | LOOP [ensure-podman : Find distribution installation] 2025-10-06 00:09:06.073347 | controller | ok: "/var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-06 00:09:06.091823 | controller | included: /var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-06 00:09:06.098332 | 2025-10-06 00:09:06.098422 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-06 00:10:21.340613 | controller | changed 2025-10-06 00:10:21.349458 | 2025-10-06 00:10:21.349612 | TASK [ensure-podman : Fetch podman version] 2025-10-06 00:10:22.064106 | controller | Client: Podman Engine 2025-10-06 00:10:22.064185 | controller | Version: 4.6.2 2025-10-06 00:10:22.064215 | controller | API Version: 4.6.2 2025-10-06 00:10:22.064241 | controller | Go Version: go1.19.12 2025-10-06 00:10:22.064277 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-06 00:10:22.064304 | controller | OS/Arch: linux/amd64 2025-10-06 00:10:22.497996 | controller | ok: Runtime: 0:00:00.195681 2025-10-06 00:10:22.511151 | 2025-10-06 00:10:22.511349 | TASK [ensure-podman : Print podman version installed] 2025-10-06 00:10:22.550782 | Podman version: Client: Podman Engine 2025-10-06 00:10:22.551031 | Version: 4.6.2 2025-10-06 00:10:22.551093 | API Version: 4.6.2 2025-10-06 00:10:22.551139 | Go Version: go1.19.12 2025-10-06 00:10:22.551180 | Built: Mon Aug 28 19:38:31 2023 2025-10-06 00:10:22.551222 | OS/Arch: linux/amd64 2025-10-06 00:10:22.563702 | 2025-10-06 00:10:22.563905 | TASK [ensure-podman : Validate podman engine] 2025-10-06 00:10:22.706196 | controller | skipping: Conditional result was False 2025-10-06 00:10:22.718948 | 2025-10-06 00:10:22.719133 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-06 00:10:22.745825 | controller | skipping: Conditional result was False 2025-10-06 00:10:22.761500 | 2025-10-06 00:10:22.761642 | TASK [Ensure python3.8 is present] 2025-10-06 00:10:22.786704 | controller | skipping: Conditional result was False 2025-10-06 00:10:22.795052 | 2025-10-06 00:10:22.795187 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-06 00:10:22.819253 | controller | ok 2025-10-06 00:10:22.845881 | 2025-10-06 00:10:22.846033 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-06 00:10:26.550345 | controller | ok: Nothing to do 2025-10-06 00:10:26.563630 | 2025-10-06 00:10:26.563837 | TASK [our-ensure-python : Also install python3-devel] 2025-10-06 00:10:39.531858 | controller | changed 2025-10-06 00:10:39.560473 | 2025-10-06 00:10:39.560628 | TASK [Run ensure-virtualenv role] 2025-10-06 00:10:39.581920 | controller | ok 2025-10-06 00:10:39.607921 | 2025-10-06 00:10:39.608081 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-06 00:10:39.960004 | controller | /usr/bin/virtualenv 2025-10-06 00:10:40.239687 | controller | ok: Runtime: 0:00:00.004626 2025-10-06 00:10:40.246640 | 2025-10-06 00:10:40.246788 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-06 00:10:40.269661 | controller | skipping: Conditional result was False 2025-10-06 00:10:40.270101 | controller | ok: All items complete 2025-10-06 00:10:40.270145 | 2025-10-06 00:10:40.288161 | 2025-10-06 00:10:40.288373 | TASK [Find the full path of the Python interpreter] 2025-10-06 00:10:40.701935 | controller | /usr/bin/python3 2025-10-06 00:10:40.930062 | controller | ok 2025-10-06 00:10:40.937184 | 2025-10-06 00:10:40.937311 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-06 00:10:42.275499 | controller | created virtual environment CPython3.11.0.final.0-64 in 738ms 2025-10-06 00:10:42.326351 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-06 00:10:42.327202 | 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-06 00:10:42.327225 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-06 00:10:42.327248 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-06 00:10:42.581039 | controller | changed 2025-10-06 00:10:42.588951 | 2025-10-06 00:10:42.589069 | TASK [Set selinux package] 2025-10-06 00:10:42.620882 | controller | ok 2025-10-06 00:10:42.627085 | 2025-10-06 00:10:42.627197 | TASK [Set selinux package (Fedora)] 2025-10-06 00:10:42.680213 | controller | ok 2025-10-06 00:10:42.686224 | 2025-10-06 00:10:42.686343 | TASK [Install selinux into virtualenv] 2025-10-06 00:10:45.270791 | controller | Collecting selinux-please-lie-to-me 2025-10-06 00:10:45.362549 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-06 00:10:45.887434 | controller | Collecting setuptools<50.0.0 2025-10-06 00:10:45.901601 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-06 00:10:46.004434 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.3 MB/s eta 0:00:00 2025-10-06 00:10:46.155858 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-06 00:10:46.156268 | controller | Attempting uninstall: setuptools 2025-10-06 00:10:46.161265 | controller | Found existing installation: setuptools 62.6.0 2025-10-06 00:10:46.273305 | controller | Uninstalling setuptools-62.6.0: 2025-10-06 00:10:46.288635 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-06 00:10:47.034615 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-06 00:10:47.244031 | controller | 2025-10-06 00:10:47.460594 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-06 00:10:47.460645 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-06 00:10:47.894516 | controller | ok: Runtime: 0:00:04.323272 2025-10-06 00:10:47.907773 | 2025-10-06 00:10:47.907957 | TASK [Install pytest-forked into virtualenv] 2025-10-06 00:10:49.044883 | controller | Collecting pytest-forked 2025-10-06 00:10:49.134494 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-06 00:10:49.192912 | controller | Collecting py 2025-10-06 00:10:49.206051 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-06 00:10:49.244881 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00 2025-10-06 00:10:49.420947 | controller | Collecting pytest>=3.10 2025-10-06 00:10:49.434195 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-06 00:10:49.499864 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.8 MB/s eta 0:00:00 2025-10-06 00:10:49.554096 | controller | Collecting iniconfig>=1 2025-10-06 00:10:49.567636 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-06 00:10:49.633919 | controller | Collecting packaging>=20 2025-10-06 00:10:49.646958 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-06 00:10:49.659683 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.4 MB/s eta 0:00:00 2025-10-06 00:10:49.705955 | controller | Collecting pluggy<2,>=1.5 2025-10-06 00:10:49.718798 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-06 00:10:49.793543 | controller | Collecting pygments>=2.7.2 2025-10-06 00:10:49.806602 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-06 00:10:49.938897 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.4 MB/s eta 0:00:00 2025-10-06 00:10:50.070974 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-06 00:10:52.333097 | 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-06 00:10:52.350670 | controller | 2025-10-06 00:10:52.536111 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-06 00:10:52.536164 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-06 00:10:53.076231 | controller | ok: Runtime: 0:00:04.223250 2025-10-06 00:10:53.082224 | 2025-10-06 00:10:53.082296 | TASK [Update pip] 2025-10-06 00:10:54.204901 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-06 00:10:54.481252 | controller | Collecting pip 2025-10-06 00:10:54.583039 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-06 00:10:54.754620 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.5 MB/s eta 0:00:00 2025-10-06 00:10:54.926185 | controller | Installing collected packages: pip 2025-10-06 00:10:54.926938 | controller | Attempting uninstall: pip 2025-10-06 00:10:54.932511 | controller | Found existing installation: pip 22.2.2 2025-10-06 00:10:55.209750 | controller | Uninstalling pip-22.2.2: 2025-10-06 00:10:55.239265 | controller | Successfully uninstalled pip-22.2.2 2025-10-06 00:10:56.931892 | controller | Successfully installed pip-25.2 2025-10-06 00:10:57.227999 | controller | ok: Runtime: 0:00:03.562734 2025-10-06 00:10:57.241907 | 2025-10-06 00:10:57.242097 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-06 00:10:57.755569 | controller | changed 2025-10-06 00:10:57.764225 | 2025-10-06 00:10:57.764353 | TASK [Install ansible into virtualenv] 2025-10-06 00:10:58.795074 | controller | Processing ./src/github.com/ansible/ansible 2025-10-06 00:10:58.801599 | controller | Installing build dependencies: started 2025-10-06 00:11:00.704071 | controller | Installing build dependencies: finished with status 'done' 2025-10-06 00:11:00.705220 | controller | Getting requirements to build wheel: started 2025-10-06 00:11:02.351790 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-06 00:11:03.352437 | controller | Preparing metadata (pyproject.toml): started 2025-10-06 00:11:03.352492 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-06 00:11:03.356674 | 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-06 00:11:03.356728 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-06 00:11:03.922402 | controller | ERROR 2025-10-06 00:11:03.922768 | controller | { 2025-10-06 00:11:03.922840 | controller | "delta": "0:00:05.336738", 2025-10-06 00:11:03.922884 | controller | "end": "2025-10-06 00:11:03.510733", 2025-10-06 00:11:03.922922 | controller | "msg": "non-zero return code", 2025-10-06 00:11:03.922977 | controller | "rc": 1, 2025-10-06 00:11:03.923015 | controller | "start": "2025-10-06 00:10:58.173995" 2025-10-06 00:11:03.923050 | controller | } failure 2025-10-06 00:11:03.925906 | 2025-10-06 00:11:03.926009 | PLAY RECAP 2025-10-06 00:11:03.926098 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-06 00:11:03.926142 | 2025-10-06 00:11:04.082540 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-06 00:11:04.084409 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-06 00:11:04.680061 | 2025-10-06 00:11:04.680184 | PLAY [all] 2025-10-06 00:11:04.701669 | 2025-10-06 00:11:04.701823 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-06 00:11:05.461256 | controller | changed: non-zero return code 2025-10-06 00:11:05.470084 | 2025-10-06 00:11:05.470206 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-06 00:11:05.484700 | controller | skipping: Conditional result was False 2025-10-06 00:11:05.490704 | 2025-10-06 00:11:05.490808 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-06 00:11:05.512751 | 2025-10-06 00:11:05.512944 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-06 00:11:05.544342 | 2025-10-06 00:11:05.544528 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-06 00:11:05.569411 | controller | skipping: Conditional result was False 2025-10-06 00:11:05.576082 | 2025-10-06 00:11:05.576207 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-06 00:11:05.608891 | 2025-10-06 00:11:05.609190 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-06 00:11:05.627787 | controller | skipping: Conditional result was False 2025-10-06 00:11:05.635183 | 2025-10-06 00:11:05.635303 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-06 00:11:05.650476 | controller | skipping: Conditional result was False 2025-10-06 00:11:05.657344 | 2025-10-06 00:11:05.657419 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-06 00:11:05.672085 | controller | skipping: Conditional result was False 2025-10-06 00:11:05.700357 | 2025-10-06 00:11:05.700435 | PLAY RECAP 2025-10-06 00:11:05.700478 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-06 00:11:05.700499 | 2025-10-06 00:11:05.810081 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-06 00:11:05.810966 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-06 00:11:06.445403 | 2025-10-06 00:11:06.445534 | PLAY [all:!appliance*] 2025-10-06 00:11:06.467154 | 2025-10-06 00:11:06.467273 | TASK [unregister the node] 2025-10-06 00:11:06.611101 | controller | skipping: Conditional result was False 2025-10-06 00:11:06.624088 | 2025-10-06 00:11:06.624289 | TASK [include_role : fetch-output] 2025-10-06 00:11:06.671578 | controller | ok 2025-10-06 00:11:06.700336 | 2025-10-06 00:11:06.700500 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-06 00:11:06.769975 | controller | skipping: Conditional result was False 2025-10-06 00:11:06.779284 | 2025-10-06 00:11:06.779584 | TASK [fetch-output : Set log path for single node] 2025-10-06 00:11:06.824118 | controller | ok 2025-10-06 00:11:06.832440 | 2025-10-06 00:11:06.832585 | LOOP [fetch-output : Ensure local output dirs] 2025-10-06 00:11:07.235781 | controller -> localhost | ok: "/var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/logs" 2025-10-06 00:11:07.540873 | controller -> localhost | changed: "/var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/artifacts" 2025-10-06 00:11:07.757247 | controller -> localhost | changed: "/var/lib/zuul/builds/d51388694ef548df951a68b59a515b34/work/docs" 2025-10-06 00:11:07.780037 | 2025-10-06 00:11:07.780188 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-06 00:11:09.068805 | controller | changed: 2025-10-06 00:11:09.069047 | controller | .d..t...... ./ 2025-10-06 00:11:09.069086 | controller | cd+++++++++ controller/ 2025-10-06 00:11:09.069145 | controller | changed: All items complete 2025-10-06 00:11:09.069178 | 2025-10-06 00:11:10.182351 | controller | changed: .d..t...... ./ 2025-10-06 00:11:11.257673 | controller | changed: .d..t...... ./ 2025-10-06 00:11:11.285303 | 2025-10-06 00:11:11.285482 | TASK [include_role : fetch-output-openshift] 2025-10-06 00:11:11.303166 | controller | skipping: Conditional result was False 2025-10-06 00:11:11.318050 | 2025-10-06 00:11:11.318221 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-06 00:11:11.354421 | controller | skipping: Conditional result was False 2025-10-06 00:11:11.368079 | controller | skipping: Conditional result was False 2025-10-06 00:11:11.428536 | 2025-10-06 00:11:11.428653 | PLAY [localhost] 2025-10-06 00:11:11.445567 | 2025-10-06 00:11:11.445655 | TASK [Run Zuul manifest role] 2025-10-06 00:11:11.466278 | localhost | ok 2025-10-06 00:11:11.484595 | 2025-10-06 00:11:11.484693 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-06 00:11:11.945807 | localhost | changed 2025-10-06 00:11:11.950521 | 2025-10-06 00:11:11.950588 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-06 00:11:11.980653 | localhost | ok 2025-10-06 00:11:11.992136 | 2025-10-06 00:11:11.992248 | TASK [Set zuul-log-path fact] 2025-10-06 00:11:12.010991 | localhost | ok 2025-10-06 00:11:12.023705 | 2025-10-06 00:11:12.023800 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-06 00:11:12.062172 | localhost | ok 2025-10-06 00:11:12.070980 | 2025-10-06 00:11:12.071061 | LOOP [Run upload-logs-swift role] 2025-10-06 00:11:12.095191 | localhost | Output suppressed because no_log was given 2025-10-06 00:11:12.128816 | 2025-10-06 00:11:12.128962 | TASK [Set zuul-log-path fact] 2025-10-06 00:11:12.154338 | localhost | skipping: Conditional result was False 2025-10-06 00:11:12.159206 | 2025-10-06 00:11:12.159273 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-06 00:11:12.580833 | localhost -> localhost | ok: Runtime: 0:00:00.006429 2025-10-06 00:11:12.586430 | 2025-10-06 00:11:12.586500 | TASK [upload-logs-swift : Upload logs to swift]