2025-10-14 00:17:34.293726 | Job console starting... 2025-10-14 00:17:34.305226 | Updating repositories 2025-10-14 00:17:34.438210 | Preparing job workspace 2025-10-14 00:17:38.459227 | Running Ansible setup... 2025-10-14 00:17:44.397902 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-14 00:17:45.015200 | 2025-10-14 00:17:45.015331 | PLAY [localhost] 2025-10-14 00:17:45.024378 | 2025-10-14 00:17:45.024466 | TASK [Gathering Facts] 2025-10-14 00:17:46.063106 | localhost | ok 2025-10-14 00:17:46.083690 | 2025-10-14 00:17:46.083853 | TASK [Setup log path fact] 2025-10-14 00:17:46.104725 | localhost | ok 2025-10-14 00:17:46.125180 | 2025-10-14 00:17:46.125325 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-14 00:17:46.166777 | localhost | ok 2025-10-14 00:17:46.179103 | 2025-10-14 00:17:46.179250 | TASK [emit-job-header : Print job information] 2025-10-14 00:17:46.222909 | # Job Information 2025-10-14 00:17:46.223149 | Ansible Version: 2.15.12 2025-10-14 00:17:46.223212 | Job: ansible-test-sanity-docker-devel 2025-10-14 00:17:46.223255 | Pipeline: periodic 2025-10-14 00:17:46.223294 | Executor: ze02.softwarefactory-project.io 2025-10-14 00:17:46.223332 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-14 00:17:46.223376 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/ca0/ansible/ca09a546f0f346fba05225d7d0f455a3/ 2025-10-14 00:17:46.223417 | Event ID: 082694bef8494c6a9293b529962a7d9e 2025-10-14 00:17:46.229773 | 2025-10-14 00:17:46.229886 | LOOP [emit-job-header : Print node information] 2025-10-14 00:17:46.336257 | localhost | ok: 2025-10-14 00:17:46.336478 | localhost | # Node Information 2025-10-14 00:17:46.336508 | localhost | Inventory Hostname: controller 2025-10-14 00:17:46.336528 | localhost | Hostname: ip-172-16-200-138 2025-10-14 00:17:46.336548 | localhost | Username: zuul-worker 2025-10-14 00:17:46.336568 | localhost | Distro: Fedora 37 2025-10-14 00:17:46.336586 | localhost | Provider: ansible-us-east-2 2025-10-14 00:17:46.336604 | localhost | Region: us-east-2 2025-10-14 00:17:46.336622 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-14 00:17:46.336644 | localhost | Product Name: t3.small 2025-10-14 00:17:46.336680 | localhost | Interface IP: 18.220.120.123 2025-10-14 00:17:46.358640 | 2025-10-14 00:17:46.358806 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-14 00:17:46.741914 | localhost -> localhost | changed 2025-10-14 00:17:46.748068 | 2025-10-14 00:17:46.748141 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-14 00:17:47.638392 | localhost -> localhost | changed 2025-10-14 00:17:47.681336 | 2025-10-14 00:17:47.681470 | PLAY [all:!appliance*] 2025-10-14 00:17:47.704288 | 2025-10-14 00:17:47.704419 | TASK [include_role : start-zuul-console] 2025-10-14 00:17:47.726618 | controller | ok 2025-10-14 00:17:47.749851 | 2025-10-14 00:17:47.749967 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-14 00:17:48.429350 | controller | ok 2025-10-14 00:17:48.454537 | 2025-10-14 00:17:48.454767 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-14 00:17:50.230488 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-14 00:17:50.245960 | 2025-10-14 00:17:50.246117 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-14 00:17:50.407158 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.417111 | 2025-10-14 00:17:50.417207 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-14 00:17:50.443250 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.462172 | 2025-10-14 00:17:50.462393 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-14 00:17:50.481355 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.492840 | 2025-10-14 00:17:50.492983 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-14 00:17:50.519362 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.529105 | 2025-10-14 00:17:50.529235 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-14 00:17:50.565244 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.575607 | 2025-10-14 00:17:50.575749 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-14 00:17:50.590449 | controller | skipping: Conditional result was False 2025-10-14 00:17:50.613952 | 2025-10-14 00:17:50.614099 | TASK [Disable Fedora Modular] 2025-10-14 00:17:51.284578 | controller | changed 2025-10-14 00:17:51.297931 | 2025-10-14 00:17:51.298125 | TASK [Enable EPEL] 2025-10-14 00:17:51.324554 | controller | skipping: Conditional result was False 2025-10-14 00:17:51.340644 | 2025-10-14 00:17:51.340927 | TASK [Register the RHEL node] 2025-10-14 00:17:51.497164 | 2025-10-14 00:17:51.497324 | TASK [Show the subscription-manager status] 2025-10-14 00:17:51.682472 | controller | skipping: Conditional result was False 2025-10-14 00:17:51.691226 | 2025-10-14 00:17:51.691330 | TASK [Enable EPEL on RHEL] 2025-10-14 00:17:51.850095 | controller | skipping: Conditional result was False 2025-10-14 00:17:51.858066 | 2025-10-14 00:17:51.858165 | TASK [Install git and tox] 2025-10-14 00:19:19.970425 | controller | changed 2025-10-14 00:19:19.979563 | 2025-10-14 00:19:19.979701 | TASK [include_role : prepare-workspace] 2025-10-14 00:19:20.012487 | controller | ok 2025-10-14 00:19:20.041322 | 2025-10-14 00:19:20.041452 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-14 00:19:20.606022 | controller | ok 2025-10-14 00:19:20.614603 | 2025-10-14 00:19:20.614748 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-14 00:19:33.851028 | controller | Output suppressed because no_log was given 2025-10-14 00:19:33.870348 | 2025-10-14 00:19:33.870485 | TASK [include_role : prepare-workspace-openshift] 2025-10-14 00:19:33.898723 | controller | skipping: Conditional result was False 2025-10-14 00:19:33.930826 | 2025-10-14 00:19:33.930927 | PLAY [all:!appliance] 2025-10-14 00:19:33.959530 | 2025-10-14 00:19:33.959683 | TASK [Run add-build-sshkey role (RSA)] 2025-10-14 00:19:33.981106 | controller | ok 2025-10-14 00:19:33.998330 | 2025-10-14 00:19:33.998446 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-14 00:19:34.217649 | controller -> localhost | ok 2025-10-14 00:19:34.232355 | 2025-10-14 00:19:34.232547 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-14 00:19:34.303757 | controller | ok 2025-10-14 00:19:34.321965 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-14 00:19:34.328444 | 2025-10-14 00:19:34.328515 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-14 00:19:34.807152 | controller -> localhost | Generating public/private rsa key pair. 2025-10-14 00:19:34.807365 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_rsa. 2025-10-14 00:19:34.807406 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_rsa.pub. 2025-10-14 00:19:34.807438 | controller -> localhost | The key fingerprint is: 2025-10-14 00:19:34.807468 | controller -> localhost | SHA256:BAfrA4aXLmhUgbM7hWTrMpEGyEr0VwT55w6rCmHNDyE zuul-build-sshkey 2025-10-14 00:19:34.807496 | controller -> localhost | The key's randomart image is: 2025-10-14 00:19:34.807524 | controller -> localhost | +---[RSA 2048]----+ 2025-10-14 00:19:34.807551 | controller -> localhost | |+..o..*+. | 2025-10-14 00:19:34.807579 | controller -> localhost | |oBo. o.+ | 2025-10-14 00:19:34.807606 | controller -> localhost | |*E*o=.o . | 2025-10-14 00:19:34.807632 | controller -> localhost | |=*+=oo o . | 2025-10-14 00:19:34.807658 | controller -> localhost | |+=++. o S | 2025-10-14 00:19:34.807730 | controller -> localhost | |=+..o o . | 2025-10-14 00:19:34.807765 | controller -> localhost | |.o. . + | 2025-10-14 00:19:34.807794 | controller -> localhost | | . . . | 2025-10-14 00:19:34.807821 | controller -> localhost | | .... | 2025-10-14 00:19:34.807852 | controller -> localhost | +----[SHA256]-----+ 2025-10-14 00:19:34.807909 | controller -> localhost | ok: Runtime: 0:00:00.051708 2025-10-14 00:19:34.816422 | 2025-10-14 00:19:34.816508 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-14 00:19:34.848556 | controller | ok 2025-10-14 00:19:34.864261 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-14 00:19:34.874552 | 2025-10-14 00:19:34.874618 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-14 00:19:34.889049 | controller | skipping: Conditional result was False 2025-10-14 00:19:34.896703 | 2025-10-14 00:19:34.896774 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-14 00:19:35.520716 | controller | changed 2025-10-14 00:19:35.533498 | 2025-10-14 00:19:35.533626 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-14 00:19:35.911850 | controller | ok 2025-10-14 00:19:35.926162 | 2025-10-14 00:19:35.926466 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-14 00:19:37.271089 | controller | changed 2025-10-14 00:19:37.280009 | 2025-10-14 00:19:37.280146 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-14 00:19:38.577436 | controller | changed 2025-10-14 00:19:38.585500 | 2025-10-14 00:19:38.586797 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-14 00:19:38.613325 | controller | skipping: Conditional result was False 2025-10-14 00:19:38.620105 | 2025-10-14 00:19:38.620184 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-14 00:19:38.972253 | controller -> localhost | changed 2025-10-14 00:19:38.986573 | 2025-10-14 00:19:38.986724 | TASK [add-build-sshkey : Add back temp key] 2025-10-14 00:19:39.280150 | controller -> localhost | Identity added: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_rsa (zuul-build-sshkey) 2025-10-14 00:19:39.280411 | controller -> localhost | ok: Runtime: 0:00:00.018564 2025-10-14 00:19:39.293474 | 2025-10-14 00:19:39.293636 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-14 00:19:39.736922 | controller | ok 2025-10-14 00:19:39.745596 | 2025-10-14 00:19:39.745712 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-14 00:19:39.790954 | controller | skipping: Conditional result was False 2025-10-14 00:19:39.808183 | 2025-10-14 00:19:39.808302 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-14 00:19:39.830396 | controller | ok 2025-10-14 00:19:39.848609 | 2025-10-14 00:19:39.848706 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-14 00:19:40.098263 | controller -> localhost | ok 2025-10-14 00:19:40.107183 | 2025-10-14 00:19:40.107276 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-14 00:19:40.135038 | controller | ok 2025-10-14 00:19:40.147050 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-14 00:19:40.153308 | 2025-10-14 00:19:40.153390 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-14 00:19:40.413020 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-14 00:19:40.413234 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_ecdsa. 2025-10-14 00:19:40.413263 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_ecdsa.pub. 2025-10-14 00:19:40.413294 | controller -> localhost | The key fingerprint is: 2025-10-14 00:19:40.413314 | controller -> localhost | SHA256:CiNGyI8A+wgIFP8kmaDfV4b5X8wtrfwVuaGDIqbOHPs zuul-build-sshkey 2025-10-14 00:19:40.413335 | controller -> localhost | The key's randomart image is: 2025-10-14 00:19:40.413354 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-14 00:19:40.413373 | controller -> localhost | |++. | 2025-10-14 00:19:40.413391 | controller -> localhost | |*oo o o | 2025-10-14 00:19:40.413410 | controller -> localhost | |B..= .o o | 2025-10-14 00:19:40.413428 | controller -> localhost | |o=o.+ + o o .| 2025-10-14 00:19:40.413447 | controller -> localhost | |..=.+.. S = o+ | 2025-10-14 00:19:40.413465 | controller -> localhost | | . . + . . o.o. +| 2025-10-14 00:19:40.413483 | controller -> localhost | | ..o ...oo ..| 2025-10-14 00:19:40.413501 | controller -> localhost | | o = . . ... | 2025-10-14 00:19:40.413519 | controller -> localhost | | .*.E . | 2025-10-14 00:19:40.413536 | controller -> localhost | +----[SHA256]-----+ 2025-10-14 00:19:40.413580 | controller -> localhost | ok: Runtime: 0:00:00.008750 2025-10-14 00:19:40.421520 | 2025-10-14 00:19:40.421632 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-14 00:19:40.442878 | controller | ok 2025-10-14 00:19:40.451092 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-14 00:19:40.461296 | 2025-10-14 00:19:40.461420 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-14 00:19:40.475775 | controller | skipping: Conditional result was False 2025-10-14 00:19:40.483377 | 2025-10-14 00:19:40.483500 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-14 00:19:40.936813 | controller | changed 2025-10-14 00:19:40.947753 | 2025-10-14 00:19:40.947896 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-14 00:19:41.293031 | controller | ok 2025-10-14 00:19:41.302433 | 2025-10-14 00:19:41.302575 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-14 00:19:42.611284 | controller | changed 2025-10-14 00:19:42.621743 | 2025-10-14 00:19:42.621864 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-14 00:19:43.911860 | controller | changed 2025-10-14 00:19:43.919117 | 2025-10-14 00:19:43.919200 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-14 00:19:43.943534 | controller | skipping: Conditional result was False 2025-10-14 00:19:43.951778 | 2025-10-14 00:19:43.951872 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-14 00:19:44.221490 | controller -> localhost | changed 2025-10-14 00:19:44.240693 | 2025-10-14 00:19:44.240849 | TASK [add-build-sshkey : Add back temp key] 2025-10-14 00:19:44.543574 | controller -> localhost | Identity added: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/ca09a546f0f346fba05225d7d0f455a3_id_ecdsa (zuul-build-sshkey) 2025-10-14 00:19:44.543868 | controller -> localhost | ok: Runtime: 0:00:00.013936 2025-10-14 00:19:44.550561 | 2025-10-14 00:19:44.550628 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-14 00:19:44.885436 | controller | ok 2025-10-14 00:19:44.897935 | 2025-10-14 00:19:44.898071 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-14 00:19:44.946253 | controller | skipping: Conditional result was False 2025-10-14 00:19:44.975214 | 2025-10-14 00:19:44.975375 | TASK [include_role : remove-zuul-sshkey] 2025-10-14 00:19:45.005299 | controller | skipping: Conditional result was False 2025-10-14 00:19:45.015115 | 2025-10-14 00:19:45.015207 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-14 00:19:45.348437 | controller | ok: "logs" 2025-10-14 00:19:45.348740 | controller | ok: All items complete 2025-10-14 00:19:45.348773 | 2025-10-14 00:19:45.650389 | controller | ok: "artifacts" 2025-10-14 00:19:45.939474 | controller | ok: "docs" 2025-10-14 00:19:45.968297 | 2025-10-14 00:19:45.968568 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-14 00:19:46.356316 | controller | changed: "logs" 2025-10-14 00:19:46.608923 | controller | changed: "artifacts" 2025-10-14 00:19:46.893566 | controller | changed: "docs" 2025-10-14 00:19:46.924903 | 2025-10-14 00:19:46.925166 | PLAY RECAP 2025-10-14 00:19:46.925230 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-14 00:19:46.925270 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-14 00:19:46.925295 | 2025-10-14 00:19:47.078752 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-14 00:19:47.079750 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-14 00:19:47.745449 | 2025-10-14 00:19:47.745584 | PLAY [all] 2025-10-14 00:19:47.768535 | 2025-10-14 00:19:47.768640 | TASK [Install binary dependencies] 2025-10-14 00:19:47.829544 | controller | ok 2025-10-14 00:19:47.850913 | 2025-10-14 00:19:47.851038 | TASK [bindep : Include find tasks] 2025-10-14 00:19:47.890719 | controller | ok 2025-10-14 00:19:47.898731 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-14 00:19:47.905232 | 2025-10-14 00:19:47.905325 | TASK [bindep : Look for bindep.txt] 2025-10-14 00:19:48.454010 | controller | ok 2025-10-14 00:19:48.468855 | 2025-10-14 00:19:48.469014 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:19:48.485747 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.498583 | 2025-10-14 00:19:48.498810 | TASK [bindep : Look for other-requirements.txt] 2025-10-14 00:19:48.806604 | controller | ok 2025-10-14 00:19:48.813862 | 2025-10-14 00:19:48.813957 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:19:48.848913 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.856791 | 2025-10-14 00:19:48.856886 | TASK [bindep : Look for bindep fallback file] 2025-10-14 00:19:48.891615 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.899554 | 2025-10-14 00:19:48.899658 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:19:48.924193 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.932003 | 2025-10-14 00:19:48.932098 | TASK [bindep : Include bindep tasks] 2025-10-14 00:19:48.956945 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.967120 | 2025-10-14 00:19:48.967273 | TASK [bindep : Include install tasks] 2025-10-14 00:19:48.991453 | controller | skipping: Conditional result was False 2025-10-14 00:19:48.999438 | 2025-10-14 00:19:48.999568 | LOOP [bindep : Include package tasks] 2025-10-14 00:19:49.059536 | 2025-10-14 00:19:49.059862 | TASK [Run test-setup role] 2025-10-14 00:19:49.082333 | controller | ok 2025-10-14 00:19:49.107308 | 2025-10-14 00:19:49.107436 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-14 00:19:49.411262 | controller | ok 2025-10-14 00:19:49.427051 | 2025-10-14 00:19:49.427239 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-14 00:19:49.587306 | controller | skipping: Conditional result was False 2025-10-14 00:19:49.642077 | 2025-10-14 00:19:49.642203 | PLAY RECAP 2025-10-14 00:19:49.642264 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-14 00:19:49.642294 | 2025-10-14 00:19:49.782388 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-14 00:19:49.783295 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-14 00:19:50.392571 | 2025-10-14 00:19:50.392737 | PLAY [controller] 2025-10-14 00:19:50.413153 | 2025-10-14 00:19:50.413261 | TASK [Create the /root directory] 2025-10-14 00:19:51.189356 | controller | ok 2025-10-14 00:19:51.195815 | 2025-10-14 00:19:51.195907 | TASK [Install glibc-langpack-en] 2025-10-14 00:19:59.291157 | controller | ok: Nothing to do 2025-10-14 00:19:59.305746 | 2025-10-14 00:19:59.305914 | TASK [Ensure controller directory exists] 2025-10-14 00:19:59.769018 | controller | changed 2025-10-14 00:19:59.776227 | 2025-10-14 00:19:59.776305 | TASK [Install container runtime] 2025-10-14 00:19:59.829464 | controller | ok 2025-10-14 00:19:59.870437 | 2025-10-14 00:19:59.870600 | LOOP [ensure-podman : Find distribution installation] 2025-10-14 00:19:59.893659 | controller | ok: "/var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-14 00:19:59.904206 | controller | included: /var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-14 00:19:59.911359 | 2025-10-14 00:19:59.911435 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-14 00:21:14.688888 | controller | changed 2025-10-14 00:21:14.703350 | 2025-10-14 00:21:14.703510 | TASK [ensure-podman : Fetch podman version] 2025-10-14 00:21:15.437992 | controller | Client: Podman Engine 2025-10-14 00:21:15.467750 | controller | Version: 4.6.2 2025-10-14 00:21:15.467790 | controller | API Version: 4.6.2 2025-10-14 00:21:15.467797 | controller | Go Version: go1.19.12 2025-10-14 00:21:15.467814 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-14 00:21:15.467821 | controller | OS/Arch: linux/amd64 2025-10-14 00:21:15.854327 | controller | ok: Runtime: 0:00:00.217825 2025-10-14 00:21:15.872265 | 2025-10-14 00:21:15.872438 | TASK [ensure-podman : Print podman version installed] 2025-10-14 00:21:15.928111 | Podman version: Client: Podman Engine 2025-10-14 00:21:15.928378 | Version: 4.6.2 2025-10-14 00:21:15.928441 | API Version: 4.6.2 2025-10-14 00:21:15.928486 | Go Version: go1.19.12 2025-10-14 00:21:15.928707 | Built: Mon Aug 28 19:38:31 2023 2025-10-14 00:21:15.928827 | OS/Arch: linux/amd64 2025-10-14 00:21:15.941117 | 2025-10-14 00:21:15.941228 | TASK [ensure-podman : Validate podman engine] 2025-10-14 00:21:16.081316 | controller | skipping: Conditional result was False 2025-10-14 00:21:16.089019 | 2025-10-14 00:21:16.089164 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-14 00:21:16.115185 | controller | skipping: Conditional result was False 2025-10-14 00:21:16.126380 | 2025-10-14 00:21:16.126452 | TASK [Ensure python3.8 is present] 2025-10-14 00:21:16.152050 | controller | skipping: Conditional result was False 2025-10-14 00:21:16.158948 | 2025-10-14 00:21:16.159026 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-14 00:21:16.191845 | controller | ok 2025-10-14 00:21:16.217402 | 2025-10-14 00:21:16.217549 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-14 00:21:20.237762 | controller | ok: Nothing to do 2025-10-14 00:21:20.250541 | 2025-10-14 00:21:20.250728 | TASK [our-ensure-python : Also install python3-devel] 2025-10-14 00:21:33.121952 | controller | changed 2025-10-14 00:21:33.138197 | 2025-10-14 00:21:33.138363 | TASK [Run ensure-virtualenv role] 2025-10-14 00:21:33.160268 | controller | ok 2025-10-14 00:21:33.183641 | 2025-10-14 00:21:33.183817 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-14 00:21:33.575362 | controller | /usr/bin/virtualenv 2025-10-14 00:21:33.815523 | controller | ok: Runtime: 0:00:00.004213 2025-10-14 00:21:33.830296 | 2025-10-14 00:21:33.830513 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-14 00:21:33.857349 | controller | skipping: Conditional result was False 2025-10-14 00:21:33.857720 | controller | ok: All items complete 2025-10-14 00:21:33.857773 | 2025-10-14 00:21:33.887041 | 2025-10-14 00:21:33.887197 | TASK [Find the full path of the Python interpreter] 2025-10-14 00:21:34.320428 | controller | /usr/bin/python3 2025-10-14 00:21:34.536901 | controller | ok 2025-10-14 00:21:34.600723 | 2025-10-14 00:21:34.600885 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-14 00:21:36.122335 | controller | created virtual environment CPython3.11.0.final.0-64 in 786ms 2025-10-14 00:21:36.171163 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-14 00:21:36.171216 | 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-14 00:21:36.171235 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-14 00:21:36.171258 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-14 00:21:36.247344 | controller | changed 2025-10-14 00:21:36.262180 | 2025-10-14 00:21:36.262375 | TASK [Set selinux package] 2025-10-14 00:21:36.302824 | controller | ok 2025-10-14 00:21:36.315905 | 2025-10-14 00:21:36.316051 | TASK [Set selinux package (Fedora)] 2025-10-14 00:21:36.359949 | controller | ok 2025-10-14 00:21:36.367912 | 2025-10-14 00:21:36.368002 | TASK [Install selinux into virtualenv] 2025-10-14 00:21:38.988346 | controller | Collecting selinux-please-lie-to-me 2025-10-14 00:21:39.080707 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-14 00:21:39.611334 | controller | Collecting setuptools<50.0.0 2025-10-14 00:21:39.625583 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-14 00:21:39.767225 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.0 MB/s eta 0:00:00 2025-10-14 00:21:39.919508 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-14 00:21:39.919828 | controller | Attempting uninstall: setuptools 2025-10-14 00:21:39.924792 | controller | Found existing installation: setuptools 62.6.0 2025-10-14 00:21:40.036092 | controller | Uninstalling setuptools-62.6.0: 2025-10-14 00:21:40.051427 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-14 00:21:40.774598 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-14 00:21:40.980468 | controller | 2025-10-14 00:21:41.187684 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-14 00:21:41.187727 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-14 00:21:41.554022 | controller | ok: Runtime: 0:00:04.313562 2025-10-14 00:21:41.570583 | 2025-10-14 00:21:41.570895 | TASK [Install pytest-forked into virtualenv] 2025-10-14 00:21:42.793956 | controller | Collecting pytest-forked 2025-10-14 00:21:42.885586 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-14 00:21:42.945397 | controller | Collecting py 2025-10-14 00:21:42.960037 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-14 00:21:42.997259 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-10-14 00:21:43.175757 | controller | Collecting pytest>=3.10 2025-10-14 00:21:43.189627 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-14 00:21:43.257528 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.6 MB/s eta 0:00:00 2025-10-14 00:21:43.311231 | controller | Collecting iniconfig>=1 2025-10-14 00:21:43.325740 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-14 00:21:43.393022 | controller | Collecting packaging>=20 2025-10-14 00:21:43.406597 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-14 00:21:43.420188 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.7 MB/s eta 0:00:00 2025-10-14 00:21:43.490595 | controller | Collecting pluggy<2,>=1.5 2025-10-14 00:21:43.504226 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-14 00:21:43.551062 | controller | Collecting pygments>=2.7.2 2025-10-14 00:21:43.564145 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-14 00:21:43.700736 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.1 MB/s eta 0:00:00 2025-10-14 00:21:43.831579 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-14 00:21:46.057966 | 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-14 00:21:46.073772 | controller | 2025-10-14 00:21:46.241919 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-14 00:21:46.241972 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-14 00:21:46.763866 | controller | ok: Runtime: 0:00:04.165304 2025-10-14 00:21:46.773350 | 2025-10-14 00:21:46.773482 | TASK [Update pip] 2025-10-14 00:21:47.864988 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-14 00:21:48.145913 | controller | Collecting pip 2025-10-14 00:21:48.249727 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-14 00:21:48.426366 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.1 MB/s eta 0:00:00 2025-10-14 00:21:48.589861 | controller | Installing collected packages: pip 2025-10-14 00:21:48.590181 | controller | Attempting uninstall: pip 2025-10-14 00:21:48.597990 | controller | Found existing installation: pip 22.2.2 2025-10-14 00:21:48.891261 | controller | Uninstalling pip-22.2.2: 2025-10-14 00:21:48.920932 | controller | Successfully uninstalled pip-22.2.2 2025-10-14 00:21:50.655857 | controller | Successfully installed pip-25.2 2025-10-14 00:21:50.937907 | controller | ok: Runtime: 0:00:03.568564 2025-10-14 00:21:50.947175 | 2025-10-14 00:21:50.947319 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-14 00:21:51.483594 | controller | changed 2025-10-14 00:21:51.498363 | 2025-10-14 00:21:51.498553 | TASK [Install ansible into virtualenv] 2025-10-14 00:21:52.624386 | controller | Processing ./src/github.com/ansible/ansible 2025-10-14 00:21:52.630782 | controller | Installing build dependencies: started 2025-10-14 00:21:54.667957 | controller | Installing build dependencies: finished with status 'done' 2025-10-14 00:21:56.274916 | controller | Getting requirements to build wheel: started 2025-10-14 00:21:56.274971 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-14 00:21:56.275352 | controller | Preparing metadata (pyproject.toml): started 2025-10-14 00:21:57.277492 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-14 00:21:57.282087 | 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-14 00:21:57.282139 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-14 00:21:57.657721 | controller | ERROR 2025-10-14 00:21:57.658025 | controller | { 2025-10-14 00:21:57.658094 | controller | "delta": "0:00:05.433950", 2025-10-14 00:21:57.658140 | controller | "end": "2025-10-14 00:21:57.423351", 2025-10-14 00:21:57.658177 | controller | "msg": "non-zero return code", 2025-10-14 00:21:57.658231 | controller | "rc": 1, 2025-10-14 00:21:57.658268 | controller | "start": "2025-10-14 00:21:51.989401" 2025-10-14 00:21:57.658303 | controller | } failure 2025-10-14 00:21:57.661069 | 2025-10-14 00:21:57.661172 | PLAY RECAP 2025-10-14 00:21:57.661256 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-14 00:21:57.661299 | 2025-10-14 00:21:57.809691 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-14 00:21:57.810806 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-14 00:21:58.454150 | 2025-10-14 00:21:58.454279 | PLAY [all] 2025-10-14 00:21:58.476596 | 2025-10-14 00:21:58.476754 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-14 00:21:59.311924 | controller | changed: non-zero return code 2025-10-14 00:21:59.319635 | 2025-10-14 00:21:59.319777 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-14 00:21:59.345762 | controller | skipping: Conditional result was False 2025-10-14 00:21:59.360936 | 2025-10-14 00:21:59.361111 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-14 00:21:59.394460 | 2025-10-14 00:21:59.394991 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-14 00:21:59.435793 | 2025-10-14 00:21:59.436204 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-14 00:21:59.455286 | controller | skipping: Conditional result was False 2025-10-14 00:21:59.472778 | 2025-10-14 00:21:59.472924 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-14 00:21:59.509315 | 2025-10-14 00:21:59.509525 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-14 00:21:59.525492 | controller | skipping: Conditional result was False 2025-10-14 00:21:59.536104 | 2025-10-14 00:21:59.536219 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-14 00:21:59.553183 | controller | skipping: Conditional result was False 2025-10-14 00:21:59.564017 | 2025-10-14 00:21:59.564137 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-14 00:21:59.579930 | controller | skipping: Conditional result was False 2025-10-14 00:21:59.621433 | 2025-10-14 00:21:59.621539 | PLAY RECAP 2025-10-14 00:21:59.621582 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-14 00:21:59.621604 | 2025-10-14 00:21:59.736230 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-14 00:21:59.737094 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-14 00:22:00.385777 | 2025-10-14 00:22:00.385926 | PLAY [all:!appliance*] 2025-10-14 00:22:00.408363 | 2025-10-14 00:22:00.408479 | TASK [unregister the node] 2025-10-14 00:22:00.543182 | controller | skipping: Conditional result was False 2025-10-14 00:22:00.555793 | 2025-10-14 00:22:00.556003 | TASK [include_role : fetch-output] 2025-10-14 00:22:00.603363 | controller | ok 2025-10-14 00:22:00.641251 | 2025-10-14 00:22:00.641400 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-14 00:22:00.718692 | controller | skipping: Conditional result was False 2025-10-14 00:22:00.726951 | 2025-10-14 00:22:00.727060 | TASK [fetch-output : Set log path for single node] 2025-10-14 00:22:00.772775 | controller | ok 2025-10-14 00:22:00.780390 | 2025-10-14 00:22:00.780502 | LOOP [fetch-output : Ensure local output dirs] 2025-10-14 00:22:01.178273 | controller -> localhost | ok: "/var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/logs" 2025-10-14 00:22:01.417305 | controller -> localhost | changed: "/var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/artifacts" 2025-10-14 00:22:01.676240 | controller -> localhost | changed: "/var/lib/zuul/builds/ca09a546f0f346fba05225d7d0f455a3/work/docs" 2025-10-14 00:22:01.695282 | 2025-10-14 00:22:01.695466 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-14 00:22:03.036800 | controller | changed: 2025-10-14 00:22:03.037126 | controller | .d..t...... ./ 2025-10-14 00:22:03.037187 | controller | cd+++++++++ controller/ 2025-10-14 00:22:03.037267 | controller | changed: All items complete 2025-10-14 00:22:03.037386 | 2025-10-14 00:22:04.150864 | controller | changed: .d..t...... ./ 2025-10-14 00:22:05.159458 | controller | changed: .d..t...... ./ 2025-10-14 00:22:05.186337 | 2025-10-14 00:22:05.186570 | TASK [include_role : fetch-output-openshift] 2025-10-14 00:22:05.212999 | controller | skipping: Conditional result was False 2025-10-14 00:22:05.222621 | 2025-10-14 00:22:05.222742 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-14 00:22:05.268447 | controller | skipping: Conditional result was False 2025-10-14 00:22:05.280814 | controller | skipping: Conditional result was False 2025-10-14 00:22:05.345539 | 2025-10-14 00:22:05.345705 | PLAY [localhost] 2025-10-14 00:22:05.371120 | 2025-10-14 00:22:05.371314 | TASK [Run Zuul manifest role] 2025-10-14 00:22:05.397544 | localhost | ok 2025-10-14 00:22:05.422334 | 2025-10-14 00:22:05.422484 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-14 00:22:05.899501 | localhost | changed 2025-10-14 00:22:05.911473 | 2025-10-14 00:22:05.911654 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-14 00:22:05.950878 | localhost | ok 2025-10-14 00:22:05.971219 | 2025-10-14 00:22:05.971378 | TASK [Set zuul-log-path fact] 2025-10-14 00:22:05.995980 | localhost | ok 2025-10-14 00:22:06.023415 | 2025-10-14 00:22:06.023606 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-14 00:22:06.059731 | localhost | ok 2025-10-14 00:22:06.076879 | 2025-10-14 00:22:06.077024 | LOOP [Run upload-logs-swift role] 2025-10-14 00:22:06.136536 | localhost | Output suppressed because no_log was given 2025-10-14 00:22:06.175621 | 2025-10-14 00:22:06.175817 | TASK [Set zuul-log-path fact] 2025-10-14 00:22:06.210978 | localhost | skipping: Conditional result was False 2025-10-14 00:22:06.219046 | 2025-10-14 00:22:06.219174 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-14 00:22:06.807425 | localhost -> localhost | ok: Runtime: 0:00:00.009774 2025-10-14 00:22:06.813193 | 2025-10-14 00:22:06.813278 | TASK [upload-logs-swift : Upload logs to swift]