2025-10-13 00:17:27.132498 | Job console starting... 2025-10-13 00:17:27.143839 | Updating repositories 2025-10-13 00:17:27.285589 | Preparing job workspace 2025-10-13 00:17:31.058010 | Running Ansible setup... 2025-10-13 00:17:37.535969 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-13 00:17:38.133157 | 2025-10-13 00:17:38.133286 | PLAY [localhost] 2025-10-13 00:17:38.141884 | 2025-10-13 00:17:38.141972 | TASK [Gathering Facts] 2025-10-13 00:17:39.128741 | localhost | ok 2025-10-13 00:17:39.153819 | 2025-10-13 00:17:39.153956 | TASK [Setup log path fact] 2025-10-13 00:17:39.171799 | localhost | ok 2025-10-13 00:17:39.184577 | 2025-10-13 00:17:39.184656 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 00:17:39.214045 | localhost | ok 2025-10-13 00:17:39.225315 | 2025-10-13 00:17:39.225458 | TASK [emit-job-header : Print job information] 2025-10-13 00:17:39.267240 | # Job Information 2025-10-13 00:17:39.267451 | Ansible Version: 2.15.12 2025-10-13 00:17:39.267491 | Job: ansible-test-sanity-docker-milestone 2025-10-13 00:17:39.267521 | Pipeline: periodic 2025-10-13 00:17:39.267548 | Executor: ze04.softwarefactory-project.io 2025-10-13 00:17:39.267574 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-13 00:17:39.267602 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/e46/ansible/e46531f0c9e0432ea834cf1365f34ad8/ 2025-10-13 00:17:39.267627 | Event ID: 5c3858b4bf9e4fdab660facb3b50ba54 2025-10-13 00:17:39.273611 | 2025-10-13 00:17:39.273727 | LOOP [emit-job-header : Print node information] 2025-10-13 00:17:39.391224 | localhost | ok: 2025-10-13 00:17:39.391482 | localhost | # Node Information 2025-10-13 00:17:39.391517 | localhost | Inventory Hostname: controller 2025-10-13 00:17:39.391540 | localhost | Hostname: ip-172-16-135-1 2025-10-13 00:17:39.391561 | localhost | Username: zuul-worker 2025-10-13 00:17:39.391588 | localhost | Distro: Fedora 37 2025-10-13 00:17:39.391656 | localhost | Provider: ansible-us-east-2 2025-10-13 00:17:39.391690 | localhost | Region: us-east-2 2025-10-13 00:17:39.391714 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-13 00:17:39.391734 | localhost | Product Name: t3.small 2025-10-13 00:17:39.391752 | localhost | Interface IP: 52.15.76.36 2025-10-13 00:17:39.413398 | 2025-10-13 00:17:39.413527 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-13 00:17:39.888047 | localhost -> localhost | changed 2025-10-13 00:17:39.901840 | 2025-10-13 00:17:39.902055 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-13 00:17:40.807360 | localhost -> localhost | changed 2025-10-13 00:17:40.838419 | 2025-10-13 00:17:40.838525 | PLAY [all:!appliance*] 2025-10-13 00:17:40.855750 | 2025-10-13 00:17:40.855846 | TASK [include_role : start-zuul-console] 2025-10-13 00:17:40.875339 | controller | ok 2025-10-13 00:17:40.889501 | 2025-10-13 00:17:40.889577 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-13 00:17:41.594127 | controller | ok 2025-10-13 00:17:41.612244 | 2025-10-13 00:17:41.612366 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-13 00:17:43.397976 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-13 00:17:43.415438 | 2025-10-13 00:17:43.415650 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-13 00:17:43.577070 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.592060 | 2025-10-13 00:17:43.592217 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-13 00:17:43.631275 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.647568 | 2025-10-13 00:17:43.647784 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-13 00:17:43.674820 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.697724 | 2025-10-13 00:17:43.697861 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-13 00:17:43.722716 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.732519 | 2025-10-13 00:17:43.732633 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-13 00:17:43.758666 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.767140 | 2025-10-13 00:17:43.767260 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-13 00:17:43.793263 | controller | skipping: Conditional result was False 2025-10-13 00:17:43.809492 | 2025-10-13 00:17:43.809581 | TASK [Disable Fedora Modular] 2025-10-13 00:17:44.621405 | controller | changed 2025-10-13 00:17:44.635333 | 2025-10-13 00:17:44.635474 | TASK [Enable EPEL] 2025-10-13 00:17:44.660788 | controller | skipping: Conditional result was False 2025-10-13 00:17:44.669229 | 2025-10-13 00:17:44.669332 | TASK [Register the RHEL node] 2025-10-13 00:17:44.842212 | 2025-10-13 00:17:44.842561 | TASK [Show the subscription-manager status] 2025-10-13 00:17:45.049896 | controller | skipping: Conditional result was False 2025-10-13 00:17:45.056943 | 2025-10-13 00:17:45.057021 | TASK [Enable EPEL on RHEL] 2025-10-13 00:17:45.197401 | controller | skipping: Conditional result was False 2025-10-13 00:17:45.210519 | 2025-10-13 00:17:45.210727 | TASK [Install git and tox] 2025-10-13 00:19:15.204124 | controller | changed 2025-10-13 00:19:15.212622 | 2025-10-13 00:19:15.212744 | TASK [include_role : prepare-workspace] 2025-10-13 00:19:15.234078 | controller | ok 2025-10-13 00:19:15.256835 | 2025-10-13 00:19:15.257088 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-13 00:19:15.765342 | controller | ok 2025-10-13 00:19:15.772197 | 2025-10-13 00:19:15.772284 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-13 00:19:28.852406 | controller | Output suppressed because no_log was given 2025-10-13 00:19:28.865716 | 2025-10-13 00:19:28.865814 | TASK [include_role : prepare-workspace-openshift] 2025-10-13 00:19:28.892475 | controller | skipping: Conditional result was False 2025-10-13 00:19:28.924790 | 2025-10-13 00:19:28.924909 | PLAY [all:!appliance] 2025-10-13 00:19:28.941889 | 2025-10-13 00:19:28.942003 | TASK [Run add-build-sshkey role (RSA)] 2025-10-13 00:19:28.972492 | controller | ok 2025-10-13 00:19:29.024786 | 2025-10-13 00:19:29.024922 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-13 00:19:29.308231 | controller -> localhost | ok 2025-10-13 00:19:29.318497 | 2025-10-13 00:19:29.318731 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-13 00:19:29.357258 | controller | ok 2025-10-13 00:19:29.381281 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-13 00:19:29.389689 | 2025-10-13 00:19:29.389798 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-13 00:19:29.936128 | controller -> localhost | Generating public/private rsa key pair. 2025-10-13 00:19:29.936396 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_rsa. 2025-10-13 00:19:29.936437 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_rsa.pub. 2025-10-13 00:19:29.936477 | controller -> localhost | The key fingerprint is: 2025-10-13 00:19:29.936506 | controller -> localhost | SHA256:hS1M9tVO8FVlNe+XOof84T9ER2dXF3qMqeRdFC3mlDk zuul-build-sshkey 2025-10-13 00:19:29.936534 | controller -> localhost | The key's randomart image is: 2025-10-13 00:19:29.936560 | controller -> localhost | +---[RSA 2048]----+ 2025-10-13 00:19:29.936586 | controller -> localhost | | o oo B^| 2025-10-13 00:19:29.936613 | controller -> localhost | | + + . .EoX| 2025-10-13 00:19:29.936640 | controller -> localhost | | + +. X.O+| 2025-10-13 00:19:29.936672 | controller -> localhost | | oo o =oo| 2025-10-13 00:19:29.936745 | controller -> localhost | | S o ...+| 2025-10-13 00:19:29.936796 | controller -> localhost | | . o..| 2025-10-13 00:19:29.936840 | controller -> localhost | | =.o | 2025-10-13 00:19:29.936885 | controller -> localhost | | =..| 2025-10-13 00:19:29.936918 | controller -> localhost | | o+| 2025-10-13 00:19:29.936949 | controller -> localhost | +----[SHA256]-----+ 2025-10-13 00:19:29.937023 | controller -> localhost | ok: Runtime: 0:00:00.156789 2025-10-13 00:19:29.947797 | 2025-10-13 00:19:29.947898 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-13 00:19:29.985254 | controller | ok 2025-10-13 00:19:29.999243 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-13 00:19:30.012047 | 2025-10-13 00:19:30.012144 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-13 00:19:30.049437 | controller | skipping: Conditional result was False 2025-10-13 00:19:30.063408 | 2025-10-13 00:19:30.063546 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-13 00:19:30.721216 | controller | changed 2025-10-13 00:19:30.729934 | 2025-10-13 00:19:30.730081 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-13 00:19:31.093395 | controller | ok 2025-10-13 00:19:31.100927 | 2025-10-13 00:19:31.101038 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-13 00:19:32.530595 | controller | changed 2025-10-13 00:19:32.547576 | 2025-10-13 00:19:32.547797 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-13 00:19:33.921482 | controller | changed 2025-10-13 00:19:33.935960 | 2025-10-13 00:19:33.936138 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-13 00:19:33.954113 | controller | skipping: Conditional result was False 2025-10-13 00:19:33.970095 | 2025-10-13 00:19:33.970296 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-13 00:19:34.306094 | controller -> localhost | changed 2025-10-13 00:19:34.329045 | 2025-10-13 00:19:34.329214 | TASK [add-build-sshkey : Add back temp key] 2025-10-13 00:19:34.610934 | controller -> localhost | Identity added: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_rsa (zuul-build-sshkey) 2025-10-13 00:19:34.611117 | controller -> localhost | ok: Runtime: 0:00:00.006992 2025-10-13 00:19:34.617416 | 2025-10-13 00:19:34.617488 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-13 00:19:35.127634 | controller | ok 2025-10-13 00:19:35.134925 | 2025-10-13 00:19:35.135077 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-13 00:19:35.163441 | controller | skipping: Conditional result was False 2025-10-13 00:19:35.180406 | 2025-10-13 00:19:35.180522 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-13 00:19:35.213137 | controller | ok 2025-10-13 00:19:35.234399 | 2025-10-13 00:19:35.234533 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-13 00:19:35.495475 | controller -> localhost | ok 2025-10-13 00:19:35.504892 | 2025-10-13 00:19:35.505036 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-13 00:19:35.530715 | controller | ok 2025-10-13 00:19:35.547382 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-13 00:19:35.556635 | 2025-10-13 00:19:35.556798 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-13 00:19:35.817530 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-13 00:19:35.817770 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_ecdsa. 2025-10-13 00:19:35.817804 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_ecdsa.pub. 2025-10-13 00:19:35.817834 | controller -> localhost | The key fingerprint is: 2025-10-13 00:19:35.817856 | controller -> localhost | SHA256:sDnDHw6jTZQRl4vcZBPg3T29x/G4jAuFCawXI0eTehk zuul-build-sshkey 2025-10-13 00:19:35.817876 | controller -> localhost | The key's randomart image is: 2025-10-13 00:19:35.817896 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-13 00:19:35.817915 | controller -> localhost | | +o=+ | 2025-10-13 00:19:35.817934 | controller -> localhost | | . BEo . . | 2025-10-13 00:19:35.817953 | controller -> localhost | | .**B=. o .. | 2025-10-13 00:19:35.817971 | controller -> localhost | | o+B=+ o . +o| 2025-10-13 00:19:35.817988 | controller -> localhost | | @.S o . o +| 2025-10-13 00:19:35.818007 | controller -> localhost | | + O . . o o | 2025-10-13 00:19:35.818025 | controller -> localhost | | . . o . . o | 2025-10-13 00:19:35.818043 | controller -> localhost | | . . | 2025-10-13 00:19:35.818061 | controller -> localhost | | . | 2025-10-13 00:19:35.818079 | controller -> localhost | +----[SHA256]-----+ 2025-10-13 00:19:35.818140 | controller -> localhost | ok: Runtime: 0:00:00.008776 2025-10-13 00:19:35.825177 | 2025-10-13 00:19:35.825282 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-13 00:19:35.854659 | controller | ok 2025-10-13 00:19:35.862239 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-13 00:19:35.872320 | 2025-10-13 00:19:35.872418 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-13 00:19:35.896531 | controller | skipping: Conditional result was False 2025-10-13 00:19:35.903189 | 2025-10-13 00:19:35.903289 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-13 00:19:36.371774 | controller | changed 2025-10-13 00:19:36.379298 | 2025-10-13 00:19:36.379394 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-13 00:19:36.755215 | controller | ok 2025-10-13 00:19:36.769275 | 2025-10-13 00:19:36.769472 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-13 00:19:38.138606 | controller | changed 2025-10-13 00:19:38.145332 | 2025-10-13 00:19:38.145415 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-13 00:19:39.534560 | controller | changed 2025-10-13 00:19:39.540596 | 2025-10-13 00:19:39.540666 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-13 00:19:39.577756 | controller | skipping: Conditional result was False 2025-10-13 00:19:39.594819 | 2025-10-13 00:19:39.595010 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-13 00:19:39.938428 | controller -> localhost | changed 2025-10-13 00:19:39.950512 | 2025-10-13 00:19:39.950626 | TASK [add-build-sshkey : Add back temp key] 2025-10-13 00:19:40.264227 | controller -> localhost | Identity added: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/e46531f0c9e0432ea834cf1365f34ad8_id_ecdsa (zuul-build-sshkey) 2025-10-13 00:19:40.264617 | controller -> localhost | ok: Runtime: 0:00:00.010068 2025-10-13 00:19:40.277567 | 2025-10-13 00:19:40.277751 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-13 00:19:40.644826 | controller | ok 2025-10-13 00:19:40.654419 | 2025-10-13 00:19:40.654700 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-13 00:19:40.702591 | controller | skipping: Conditional result was False 2025-10-13 00:19:40.721941 | 2025-10-13 00:19:40.722189 | TASK [include_role : remove-zuul-sshkey] 2025-10-13 00:19:40.751388 | controller | skipping: Conditional result was False 2025-10-13 00:19:40.761611 | 2025-10-13 00:19:40.761861 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 00:19:41.084929 | controller | ok: "logs" 2025-10-13 00:19:41.085198 | controller | ok: All items complete 2025-10-13 00:19:41.085229 | 2025-10-13 00:19:41.464377 | controller | ok: "artifacts" 2025-10-13 00:19:41.705464 | controller | ok: "docs" 2025-10-13 00:19:41.714159 | 2025-10-13 00:19:41.714294 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 00:19:42.072264 | controller | changed: "logs" 2025-10-13 00:19:42.374403 | controller | changed: "artifacts" 2025-10-13 00:19:42.681132 | controller | changed: "docs" 2025-10-13 00:19:42.729234 | 2025-10-13 00:19:42.729353 | PLAY RECAP 2025-10-13 00:19:42.729399 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-13 00:19:42.729426 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 00:19:42.729443 | 2025-10-13 00:19:42.849103 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-13 00:19:42.849962 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 00:19:43.452139 | 2025-10-13 00:19:43.452273 | PLAY [all] 2025-10-13 00:19:43.475640 | 2025-10-13 00:19:43.475789 | TASK [Install binary dependencies] 2025-10-13 00:19:43.556846 | controller | ok 2025-10-13 00:19:43.578768 | 2025-10-13 00:19:43.578945 | TASK [bindep : Include find tasks] 2025-10-13 00:19:43.612242 | controller | ok 2025-10-13 00:19:43.624012 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-13 00:19:43.633963 | 2025-10-13 00:19:43.634082 | TASK [bindep : Look for bindep.txt] 2025-10-13 00:19:44.174457 | controller | ok 2025-10-13 00:19:44.181118 | 2025-10-13 00:19:44.181235 | TASK [bindep : Define bindep_file fact] 2025-10-13 00:19:44.195473 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.203629 | 2025-10-13 00:19:44.203805 | TASK [bindep : Look for other-requirements.txt] 2025-10-13 00:19:44.546096 | controller | ok 2025-10-13 00:19:44.556416 | 2025-10-13 00:19:44.556605 | TASK [bindep : Define bindep_file fact] 2025-10-13 00:19:44.582702 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.591363 | 2025-10-13 00:19:44.591505 | TASK [bindep : Look for bindep fallback file] 2025-10-13 00:19:44.617233 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.629382 | 2025-10-13 00:19:44.629556 | TASK [bindep : Define bindep_file fact] 2025-10-13 00:19:44.655404 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.662541 | 2025-10-13 00:19:44.662674 | TASK [bindep : Include bindep tasks] 2025-10-13 00:19:44.687463 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.695578 | 2025-10-13 00:19:44.695743 | TASK [bindep : Include install tasks] 2025-10-13 00:19:44.720405 | controller | skipping: Conditional result was False 2025-10-13 00:19:44.727301 | 2025-10-13 00:19:44.727446 | LOOP [bindep : Include package tasks] 2025-10-13 00:19:44.796073 | 2025-10-13 00:19:44.796347 | TASK [Run test-setup role] 2025-10-13 00:19:44.818281 | controller | ok 2025-10-13 00:19:44.845819 | 2025-10-13 00:19:44.845978 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-13 00:19:45.792376 | controller | ok 2025-10-13 00:19:45.801025 | 2025-10-13 00:19:45.801119 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-13 00:19:45.941703 | controller | skipping: Conditional result was False 2025-10-13 00:19:45.967872 | 2025-10-13 00:19:45.968004 | PLAY RECAP 2025-10-13 00:19:45.968049 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-13 00:19:45.968074 | 2025-10-13 00:19:46.081468 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 00:19:46.083789 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-13 00:19:46.696079 | 2025-10-13 00:19:46.696209 | PLAY [controller] 2025-10-13 00:19:46.715839 | 2025-10-13 00:19:46.715969 | TASK [Create the /root directory] 2025-10-13 00:19:47.381043 | controller | ok 2025-10-13 00:19:47.388497 | 2025-10-13 00:19:47.388586 | TASK [Install glibc-langpack-en] 2025-10-13 00:19:55.512560 | controller | ok: Nothing to do 2025-10-13 00:19:55.518290 | 2025-10-13 00:19:55.518375 | TASK [Ensure controller directory exists] 2025-10-13 00:19:56.046865 | controller | changed 2025-10-13 00:19:56.058904 | 2025-10-13 00:19:56.059058 | TASK [Install container runtime] 2025-10-13 00:19:56.139264 | controller | ok 2025-10-13 00:19:56.202735 | 2025-10-13 00:19:56.202881 | LOOP [ensure-podman : Find distribution installation] 2025-10-13 00:19:56.233746 | controller | ok: "/var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-13 00:19:56.248247 | controller | included: /var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-13 00:19:56.258351 | 2025-10-13 00:19:56.258522 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-13 00:21:12.511793 | controller | changed 2025-10-13 00:21:12.521318 | 2025-10-13 00:21:12.521445 | TASK [ensure-podman : Fetch podman version] 2025-10-13 00:21:13.298842 | controller | Client: Podman Engine 2025-10-13 00:21:13.325797 | controller | Version: 4.6.2 2025-10-13 00:21:13.325837 | controller | API Version: 4.6.2 2025-10-13 00:21:13.325844 | controller | Go Version: go1.19.12 2025-10-13 00:21:13.325860 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-13 00:21:13.325867 | controller | OS/Arch: linux/amd64 2025-10-13 00:21:13.670620 | controller | ok: Runtime: 0:00:00.221733 2025-10-13 00:21:13.677051 | 2025-10-13 00:21:13.677139 | TASK [ensure-podman : Print podman version installed] 2025-10-13 00:21:13.716888 | Podman version: Client: Podman Engine 2025-10-13 00:21:13.717038 | Version: 4.6.2 2025-10-13 00:21:13.717066 | API Version: 4.6.2 2025-10-13 00:21:13.717087 | Go Version: go1.19.12 2025-10-13 00:21:13.717106 | Built: Mon Aug 28 19:38:31 2023 2025-10-13 00:21:13.717128 | OS/Arch: linux/amd64 2025-10-13 00:21:13.724369 | 2025-10-13 00:21:13.724469 | TASK [ensure-podman : Validate podman engine] 2025-10-13 00:21:13.867365 | controller | skipping: Conditional result was False 2025-10-13 00:21:13.877063 | 2025-10-13 00:21:13.877210 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-13 00:21:13.892526 | controller | skipping: Conditional result was False 2025-10-13 00:21:13.908087 | 2025-10-13 00:21:13.908223 | TASK [Ensure python3.8 is present] 2025-10-13 00:21:13.934148 | controller | skipping: Conditional result was False 2025-10-13 00:21:13.943694 | 2025-10-13 00:21:13.943840 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-13 00:21:13.967914 | controller | ok 2025-10-13 00:21:13.997033 | 2025-10-13 00:21:13.997163 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-13 00:21:17.891061 | controller | ok: Nothing to do 2025-10-13 00:21:17.905069 | 2025-10-13 00:21:17.905239 | TASK [our-ensure-python : Also install python3-devel] 2025-10-13 00:21:30.970562 | controller | changed 2025-10-13 00:21:30.980768 | 2025-10-13 00:21:30.980843 | TASK [Run ensure-virtualenv role] 2025-10-13 00:21:31.004531 | controller | ok 2025-10-13 00:21:31.034091 | 2025-10-13 00:21:31.034211 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-13 00:21:31.408802 | controller | /usr/bin/virtualenv 2025-10-13 00:21:31.666997 | controller | ok: Runtime: 0:00:00.004281 2025-10-13 00:21:31.673055 | 2025-10-13 00:21:31.673130 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-13 00:21:31.707424 | controller | skipping: Conditional result was False 2025-10-13 00:21:31.707801 | controller | ok: All items complete 2025-10-13 00:21:31.707850 | 2025-10-13 00:21:31.725893 | 2025-10-13 00:21:31.726080 | TASK [Find the full path of the Python interpreter] 2025-10-13 00:21:32.209124 | controller | /usr/bin/python3 2025-10-13 00:21:32.412458 | controller | ok 2025-10-13 00:21:32.420048 | 2025-10-13 00:21:32.420178 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-13 00:21:33.851567 | controller | created virtual environment CPython3.11.0.final.0-64 in 779ms 2025-10-13 00:21:33.892945 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-13 00:21:33.893003 | 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-13 00:21:33.893021 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-13 00:21:33.893044 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-13 00:21:34.052145 | controller | changed 2025-10-13 00:21:34.058354 | 2025-10-13 00:21:34.058438 | TASK [Set selinux package] 2025-10-13 00:21:34.077720 | controller | ok 2025-10-13 00:21:34.083136 | 2025-10-13 00:21:34.083227 | TASK [Set selinux package (Fedora)] 2025-10-13 00:21:34.115526 | controller | ok 2025-10-13 00:21:34.123220 | 2025-10-13 00:21:34.123343 | TASK [Install selinux into virtualenv] 2025-10-13 00:21:36.739498 | controller | Collecting selinux-please-lie-to-me 2025-10-13 00:21:36.861322 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-13 00:21:37.388333 | controller | Collecting setuptools<50.0.0 2025-10-13 00:21:37.407248 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-13 00:21:37.516644 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.6 MB/s eta 0:00:00 2025-10-13 00:21:37.670440 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-13 00:21:37.670886 | controller | Attempting uninstall: setuptools 2025-10-13 00:21:37.675803 | controller | Found existing installation: setuptools 62.6.0 2025-10-13 00:21:37.787730 | controller | Uninstalling setuptools-62.6.0: 2025-10-13 00:21:37.802889 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-13 00:21:38.575230 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-13 00:21:38.786215 | controller | 2025-10-13 00:21:39.004745 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-13 00:21:39.004802 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-13 00:21:39.287827 | controller | ok: Runtime: 0:00:04.391945 2025-10-13 00:21:39.303269 | 2025-10-13 00:21:39.303463 | TASK [Install pytest-forked into virtualenv] 2025-10-13 00:21:40.528659 | controller | Collecting pytest-forked 2025-10-13 00:21:40.618479 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-13 00:21:40.679587 | controller | Collecting py 2025-10-13 00:21:40.692251 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-13 00:21:40.726278 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-10-13 00:21:40.902352 | controller | Collecting pytest>=3.10 2025-10-13 00:21:40.915863 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-13 00:21:40.977361 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-10-13 00:21:41.133569 | controller | Collecting iniconfig>=1 2025-10-13 00:21:41.146904 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-13 00:21:41.238367 | controller | Collecting packaging>=20 2025-10-13 00:21:41.258931 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-13 00:21:41.270929 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.0 MB/s eta 0:00:00 2025-10-13 00:21:41.318817 | controller | Collecting pluggy<2,>=1.5 2025-10-13 00:21:41.330690 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-13 00:21:41.405231 | controller | Collecting pygments>=2.7.2 2025-10-13 00:21:41.418325 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-13 00:21:41.536783 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.6 MB/s eta 0:00:00 2025-10-13 00:21:41.668222 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-13 00:21:43.937993 | 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-13 00:21:43.954317 | controller | 2025-10-13 00:21:44.140324 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-13 00:21:44.140377 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-13 00:21:44.484364 | controller | ok: Runtime: 0:00:04.344337 2025-10-13 00:21:44.490785 | 2025-10-13 00:21:44.490853 | TASK [Update pip] 2025-10-13 00:21:45.768778 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-13 00:21:46.054453 | controller | Collecting pip 2025-10-13 00:21:46.157487 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-13 00:21:46.316211 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.4 MB/s eta 0:00:00 2025-10-13 00:21:46.476076 | controller | Installing collected packages: pip 2025-10-13 00:21:46.476371 | controller | Attempting uninstall: pip 2025-10-13 00:21:46.483938 | controller | Found existing installation: pip 22.2.2 2025-10-13 00:21:46.759438 | controller | Uninstalling pip-22.2.2: 2025-10-13 00:21:46.810481 | controller | Successfully uninstalled pip-22.2.2 2025-10-13 00:21:48.507553 | controller | Successfully installed pip-25.2 2025-10-13 00:21:49.157998 | controller | ok: Runtime: 0:00:03.637976 2025-10-13 00:21:49.171178 | 2025-10-13 00:21:49.171329 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-13 00:21:49.791828 | controller | changed 2025-10-13 00:21:49.797251 | 2025-10-13 00:21:49.797318 | TASK [Install ansible into virtualenv] 2025-10-13 00:21:50.859499 | controller | Processing ./src/github.com/ansible/ansible 2025-10-13 00:21:50.868955 | controller | Installing build dependencies: started 2025-10-13 00:21:53.010957 | controller | Installing build dependencies: finished with status 'done' 2025-10-13 00:21:53.012076 | controller | Getting requirements to build wheel: started 2025-10-13 00:21:54.548550 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-13 00:21:55.463528 | controller | Preparing metadata (pyproject.toml): started 2025-10-13 00:21:55.463582 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-13 00:21:55.467292 | 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-13 00:21:55.472072 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-13 00:21:55.937694 | controller | ERROR 2025-10-13 00:21:55.937873 | controller | { 2025-10-13 00:21:55.937903 | controller | "delta": "0:00:05.389607", 2025-10-13 00:21:55.937924 | controller | "end": "2025-10-13 00:21:55.619209", 2025-10-13 00:21:55.937942 | controller | "msg": "non-zero return code", 2025-10-13 00:21:55.937980 | controller | "rc": 1, 2025-10-13 00:21:55.937998 | controller | "start": "2025-10-13 00:21:50.229602" 2025-10-13 00:21:55.938015 | controller | } failure 2025-10-13 00:21:55.940129 | 2025-10-13 00:21:55.940181 | PLAY RECAP 2025-10-13 00:21:55.940222 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-13 00:21:55.940242 | 2025-10-13 00:21:56.065374 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-13 00:21:56.066571 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 00:21:56.691197 | 2025-10-13 00:21:56.691324 | PLAY [all] 2025-10-13 00:21:56.713928 | 2025-10-13 00:21:56.714064 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-13 00:21:57.572210 | controller | changed: non-zero return code 2025-10-13 00:21:57.586088 | 2025-10-13 00:21:57.586318 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-13 00:21:57.613995 | controller | skipping: Conditional result was False 2025-10-13 00:21:57.623415 | 2025-10-13 00:21:57.623535 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-13 00:21:57.660037 | 2025-10-13 00:21:57.660252 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-13 00:21:57.695750 | 2025-10-13 00:21:57.695952 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-13 00:21:57.721608 | controller | skipping: Conditional result was False 2025-10-13 00:21:57.731208 | 2025-10-13 00:21:57.731318 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-13 00:21:57.777473 | 2025-10-13 00:21:57.777705 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-13 00:21:57.802973 | controller | skipping: Conditional result was False 2025-10-13 00:21:57.811428 | 2025-10-13 00:21:57.811521 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-13 00:21:57.836507 | controller | skipping: Conditional result was False 2025-10-13 00:21:57.845476 | 2025-10-13 00:21:57.845568 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-13 00:21:57.871168 | controller | skipping: Conditional result was False 2025-10-13 00:21:57.900222 | 2025-10-13 00:21:57.900325 | PLAY RECAP 2025-10-13 00:21:57.900380 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-13 00:21:57.900411 | 2025-10-13 00:21:58.012086 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 00:21:58.013877 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-13 00:21:58.652697 | 2025-10-13 00:21:58.652818 | PLAY [all:!appliance*] 2025-10-13 00:21:58.674606 | 2025-10-13 00:21:58.674743 | TASK [unregister the node] 2025-10-13 00:21:58.803359 | controller | skipping: Conditional result was False 2025-10-13 00:21:58.809585 | 2025-10-13 00:21:58.809665 | TASK [include_role : fetch-output] 2025-10-13 00:21:58.839790 | controller | ok 2025-10-13 00:21:58.859642 | 2025-10-13 00:21:58.859751 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-13 00:21:58.915570 | controller | skipping: Conditional result was False 2025-10-13 00:21:58.922761 | 2025-10-13 00:21:58.922879 | TASK [fetch-output : Set log path for single node] 2025-10-13 00:21:58.967227 | controller | ok 2025-10-13 00:21:58.975591 | 2025-10-13 00:21:58.975755 | LOOP [fetch-output : Ensure local output dirs] 2025-10-13 00:21:59.357871 | controller -> localhost | ok: "/var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/logs" 2025-10-13 00:21:59.633291 | controller -> localhost | changed: "/var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/artifacts" 2025-10-13 00:21:59.897602 | controller -> localhost | changed: "/var/lib/zuul/builds/e46531f0c9e0432ea834cf1365f34ad8/work/docs" 2025-10-13 00:21:59.915116 | 2025-10-13 00:21:59.915275 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-13 00:22:01.184983 | controller | changed: 2025-10-13 00:22:01.185507 | controller | .d..t...... ./ 2025-10-13 00:22:01.185605 | controller | cd+++++++++ controller/ 2025-10-13 00:22:01.185741 | controller | changed: All items complete 2025-10-13 00:22:01.185867 | 2025-10-13 00:22:02.816930 | controller | changed: .d..t...... ./ 2025-10-13 00:22:03.914091 | controller | changed: .d..t...... ./ 2025-10-13 00:22:03.936258 | 2025-10-13 00:22:03.936382 | TASK [include_role : fetch-output-openshift] 2025-10-13 00:22:03.960736 | controller | skipping: Conditional result was False 2025-10-13 00:22:03.967039 | 2025-10-13 00:22:03.967114 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-13 00:22:04.003989 | controller | skipping: Conditional result was False 2025-10-13 00:22:04.015908 | controller | skipping: Conditional result was False 2025-10-13 00:22:04.050231 | 2025-10-13 00:22:04.050356 | PLAY [localhost] 2025-10-13 00:22:04.062882 | 2025-10-13 00:22:04.062956 | TASK [Run Zuul manifest role] 2025-10-13 00:22:04.080951 | localhost | ok 2025-10-13 00:22:04.095183 | 2025-10-13 00:22:04.095262 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-13 00:22:04.510791 | localhost | changed 2025-10-13 00:22:04.515433 | 2025-10-13 00:22:04.515513 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-13 00:22:04.543404 | localhost | ok 2025-10-13 00:22:04.551627 | 2025-10-13 00:22:04.551755 | TASK [Set zuul-log-path fact] 2025-10-13 00:22:04.569957 | localhost | ok 2025-10-13 00:22:04.583780 | 2025-10-13 00:22:04.583852 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 00:22:04.613595 | localhost | ok 2025-10-13 00:22:04.623520 | 2025-10-13 00:22:04.623582 | LOOP [Run upload-logs-swift role] 2025-10-13 00:22:04.648125 | localhost | Output suppressed because no_log was given 2025-10-13 00:22:04.673552 | 2025-10-13 00:22:04.673669 | TASK [Set zuul-log-path fact] 2025-10-13 00:22:04.697605 | localhost | skipping: Conditional result was False 2025-10-13 00:22:04.702991 | 2025-10-13 00:22:04.703059 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-13 00:22:05.136582 | localhost -> localhost | ok: Runtime: 0:00:00.004972 2025-10-13 00:22:05.170110 | 2025-10-13 00:22:05.170229 | TASK [upload-logs-swift : Upload logs to swift]