2025-12-10 00:12:52.029316 | Job console starting... 2025-12-10 00:12:52.042581 | Updating repositories 2025-12-10 00:12:52.191606 | Preparing job workspace 2025-12-10 00:12:55.933796 | Running Ansible setup... 2025-12-10 00:13:00.290495 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-10 00:13:00.882078 | 2025-12-10 00:13:00.882191 | PLAY [localhost] 2025-12-10 00:13:00.891376 | 2025-12-10 00:13:00.891453 | TASK [Gathering Facts] 2025-12-10 00:13:01.891312 | localhost | ok 2025-12-10 00:13:01.906068 | 2025-12-10 00:13:01.906171 | TASK [Setup log path fact] 2025-12-10 00:13:01.939363 | localhost | ok 2025-12-10 00:13:01.962498 | 2025-12-10 00:13:01.962615 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-10 00:13:02.002505 | localhost | ok 2025-12-10 00:13:02.011816 | 2025-12-10 00:13:02.011915 | TASK [emit-job-header : Print job information] 2025-12-10 00:13:02.050821 | # Job Information 2025-12-10 00:13:02.050976 | Ansible Version: 2.15.12 2025-12-10 00:13:02.051006 | Job: ansible-test-sanity-docker-milestone 2025-12-10 00:13:02.051026 | Pipeline: periodic 2025-12-10 00:13:02.051043 | Executor: ze03.softwarefactory-project.io 2025-12-10 00:13:02.051061 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-10 00:13:02.051081 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/1b4/ansible/1b454643945d4353942f07b5c1538397/ 2025-12-10 00:13:02.051099 | Event ID: 6e49960649da492f963de05b327e4f7a 2025-12-10 00:13:02.055006 | 2025-12-10 00:13:02.055069 | LOOP [emit-job-header : Print node information] 2025-12-10 00:13:02.174269 | localhost | ok: 2025-12-10 00:13:02.174595 | localhost | # Node Information 2025-12-10 00:13:02.174644 | localhost | Inventory Hostname: controller 2025-12-10 00:13:02.174678 | localhost | Hostname: np0005552595 2025-12-10 00:13:02.174710 | localhost | Username: zuul 2025-12-10 00:13:02.174796 | localhost | Distro: Fedora 37 2025-12-10 00:13:02.174836 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-10 00:13:02.174869 | localhost | Region: ca-ymq-1 2025-12-10 00:13:02.174899 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-10 00:13:02.174928 | localhost | Product Name: OpenStack Nova 2025-12-10 00:13:02.174958 | localhost | Interface IP: 162.253.55.187 2025-12-10 00:13:02.192348 | 2025-12-10 00:13:02.192532 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-10 00:13:02.648807 | localhost -> localhost | changed 2025-12-10 00:13:02.656608 | 2025-12-10 00:13:02.656742 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-10 00:13:03.655171 | localhost -> localhost | changed 2025-12-10 00:13:03.698387 | 2025-12-10 00:13:03.698487 | PLAY [all:!appliance*] 2025-12-10 00:13:03.725317 | 2025-12-10 00:13:03.725430 | TASK [include_role : start-zuul-console] 2025-12-10 00:13:03.757904 | controller | ok 2025-12-10 00:13:03.797961 | 2025-12-10 00:13:03.798187 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-10 00:13:04.154442 | controller | ok 2025-12-10 00:13:04.178198 | 2025-12-10 00:13:04.178346 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-10 00:13:26.540461 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-10 00:13:26.555210 | 2025-12-10 00:13:26.555358 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-10 00:13:27.103217 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.116824 | 2025-12-10 00:13:27.117019 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-10 00:13:27.145801 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.162709 | 2025-12-10 00:13:27.162916 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-10 00:13:27.192111 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.202025 | 2025-12-10 00:13:27.202150 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-10 00:13:27.216456 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.226380 | 2025-12-10 00:13:27.226495 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-10 00:13:27.251112 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.260600 | 2025-12-10 00:13:27.260697 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-10 00:13:27.286604 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.304783 | 2025-12-10 00:13:27.304910 | TASK [Disable Fedora Modular] 2025-12-10 00:13:27.707395 | controller | changed 2025-12-10 00:13:27.715577 | 2025-12-10 00:13:27.715669 | TASK [Enable EPEL] 2025-12-10 00:13:27.741879 | controller | skipping: Conditional result was False 2025-12-10 00:13:27.751812 | 2025-12-10 00:13:27.751939 | TASK [Register the RHEL node] 2025-12-10 00:13:28.314824 | 2025-12-10 00:13:28.315080 | TASK [Show the subscription-manager status] 2025-12-10 00:13:28.873097 | controller | skipping: Conditional result was False 2025-12-10 00:13:28.881673 | 2025-12-10 00:13:28.881777 | TASK [Enable EPEL on RHEL] 2025-12-10 00:13:29.436454 | controller | skipping: Conditional result was False 2025-12-10 00:13:29.450413 | 2025-12-10 00:13:29.450591 | TASK [Install git and tox] 2025-12-10 00:16:41.644554 | controller | changed 2025-12-10 00:16:41.655122 | 2025-12-10 00:16:41.655204 | TASK [include_role : prepare-workspace] 2025-12-10 00:16:41.688150 | controller | ok 2025-12-10 00:16:41.717618 | 2025-12-10 00:16:41.717745 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-10 00:16:41.949895 | controller | ok 2025-12-10 00:16:41.965084 | 2025-12-10 00:16:41.965218 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-10 00:16:53.803892 | controller | Output suppressed because no_log was given 2025-12-10 00:16:53.820156 | 2025-12-10 00:16:53.820244 | TASK [include_role : prepare-workspace-openshift] 2025-12-10 00:16:53.850654 | controller | skipping: Conditional result was False 2025-12-10 00:16:53.882656 | 2025-12-10 00:16:53.882874 | PLAY [all:!appliance] 2025-12-10 00:16:53.904385 | 2025-12-10 00:16:53.904466 | TASK [Run add-build-sshkey role (RSA)] 2025-12-10 00:16:53.947302 | controller | ok 2025-12-10 00:16:53.962060 | 2025-12-10 00:16:53.962136 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-10 00:16:54.283353 | controller -> localhost | ok 2025-12-10 00:16:54.296998 | 2025-12-10 00:16:54.297134 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-10 00:16:54.335812 | controller | ok 2025-12-10 00:16:54.363072 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-10 00:16:54.372626 | 2025-12-10 00:16:54.372722 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-10 00:16:54.967467 | controller -> localhost | Generating public/private rsa key pair. 2025-12-10 00:16:54.967800 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_rsa. 2025-12-10 00:16:54.967849 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_rsa.pub. 2025-12-10 00:16:54.967882 | controller -> localhost | The key fingerprint is: 2025-12-10 00:16:54.967910 | controller -> localhost | SHA256:dvApXC2zjOxge793rQ4Vm/Ut2xFcBpoHqBMNweWcjxA zuul-build-sshkey 2025-12-10 00:16:54.967938 | controller -> localhost | The key's randomart image is: 2025-12-10 00:16:54.967965 | controller -> localhost | +---[RSA 2048]----+ 2025-12-10 00:16:54.967991 | controller -> localhost | | .E=... ..o| 2025-12-10 00:16:54.968018 | controller -> localhost | | o+oo +...| 2025-12-10 00:16:54.968043 | controller -> localhost | | ooB + oo.| 2025-12-10 00:16:54.968068 | controller -> localhost | | ooB B . =+| 2025-12-10 00:16:54.968097 | controller -> localhost | | o S.B . =.o| 2025-12-10 00:16:54.968133 | controller -> localhost | | . = o . +.| 2025-12-10 00:16:54.968169 | controller -> localhost | | . o . ...| 2025-12-10 00:16:54.968198 | controller -> localhost | | . . ... .| 2025-12-10 00:16:54.968224 | controller -> localhost | | oo oo. | 2025-12-10 00:16:54.968254 | controller -> localhost | +----[SHA256]-----+ 2025-12-10 00:16:54.968484 | controller -> localhost | ok: Runtime: 0:00:00.138503 2025-12-10 00:16:54.979285 | 2025-12-10 00:16:54.979395 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-10 00:16:55.012709 | controller | ok 2025-12-10 00:16:55.026565 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-10 00:16:55.041402 | 2025-12-10 00:16:55.041551 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-10 00:16:55.077774 | controller | skipping: Conditional result was False 2025-12-10 00:16:55.087995 | 2025-12-10 00:16:55.088091 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-10 00:16:55.519089 | controller | changed 2025-12-10 00:16:55.528139 | 2025-12-10 00:16:55.528253 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-10 00:16:55.756313 | controller | ok 2025-12-10 00:16:55.812017 | 2025-12-10 00:16:55.812150 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-10 00:16:56.424693 | controller | changed 2025-12-10 00:16:56.430812 | 2025-12-10 00:16:56.430880 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-10 00:16:57.020425 | controller | changed 2025-12-10 00:16:57.027238 | 2025-12-10 00:16:57.027315 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-10 00:16:57.051607 | controller | skipping: Conditional result was False 2025-12-10 00:16:57.060478 | 2025-12-10 00:16:57.060602 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-10 00:16:57.452343 | controller -> localhost | changed 2025-12-10 00:16:57.470783 | 2025-12-10 00:16:57.470907 | TASK [add-build-sshkey : Add back temp key] 2025-12-10 00:16:57.782801 | controller -> localhost | Identity added: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_rsa (zuul-build-sshkey) 2025-12-10 00:16:57.783279 | controller -> localhost | ok: Runtime: 0:00:00.010538 2025-12-10 00:16:57.811970 | 2025-12-10 00:16:57.815850 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-10 00:16:58.115920 | controller | ok 2025-12-10 00:16:58.124414 | 2025-12-10 00:16:58.124507 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-10 00:16:58.150283 | controller | skipping: Conditional result was False 2025-12-10 00:16:58.166574 | 2025-12-10 00:16:58.166664 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-10 00:16:58.190148 | controller | ok 2025-12-10 00:16:58.217834 | 2025-12-10 00:16:58.217936 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-10 00:16:58.467447 | controller -> localhost | ok 2025-12-10 00:16:58.479700 | 2025-12-10 00:16:58.479847 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-10 00:16:58.500418 | controller | ok 2025-12-10 00:16:58.513233 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-10 00:16:58.520311 | 2025-12-10 00:16:58.520376 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-10 00:16:58.788052 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-10 00:16:58.788260 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_ecdsa. 2025-12-10 00:16:58.788290 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_ecdsa.pub. 2025-12-10 00:16:58.788320 | controller -> localhost | The key fingerprint is: 2025-12-10 00:16:58.788340 | controller -> localhost | SHA256:fxHCfNAnlm2A1oB4H0IZAX2Ek6zC2PgxXQtXtVbur3o zuul-build-sshkey 2025-12-10 00:16:58.788361 | controller -> localhost | The key's randomart image is: 2025-12-10 00:16:58.788379 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-10 00:16:58.788397 | controller -> localhost | | .*+X=*o+. | 2025-12-10 00:16:58.788414 | controller -> localhost | | o &o=.*++ | 2025-12-10 00:16:58.788431 | controller -> localhost | | = . * B+o=+. | 2025-12-10 00:16:58.788448 | controller -> localhost | | o * o . .+ o | 2025-12-10 00:16:58.788464 | controller -> localhost | | . + S . . | 2025-12-10 00:16:58.788481 | controller -> localhost | | . . . . | 2025-12-10 00:16:58.788498 | controller -> localhost | | . . .| 2025-12-10 00:16:58.788514 | controller -> localhost | | . E. | 2025-12-10 00:16:58.788531 | controller -> localhost | | .o. | 2025-12-10 00:16:58.788547 | controller -> localhost | +----[SHA256]-----+ 2025-12-10 00:16:58.788596 | controller -> localhost | ok: Runtime: 0:00:00.007727 2025-12-10 00:16:58.796030 | 2025-12-10 00:16:58.796125 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-10 00:16:58.816989 | controller | ok 2025-12-10 00:16:58.824657 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-10 00:16:58.833930 | 2025-12-10 00:16:58.833995 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-10 00:16:58.849001 | controller | skipping: Conditional result was False 2025-12-10 00:16:58.856155 | 2025-12-10 00:16:58.856228 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-10 00:16:59.120661 | controller | changed 2025-12-10 00:16:59.136283 | 2025-12-10 00:16:59.136429 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-10 00:16:59.355917 | controller | ok 2025-12-10 00:16:59.361629 | 2025-12-10 00:16:59.361695 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-10 00:16:59.995753 | controller | changed 2025-12-10 00:17:00.014819 | 2025-12-10 00:17:00.014962 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-10 00:17:00.665885 | controller | changed 2025-12-10 00:17:00.678767 | 2025-12-10 00:17:00.678915 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-10 00:17:00.707763 | controller | skipping: Conditional result was False 2025-12-10 00:17:00.722674 | 2025-12-10 00:17:00.722945 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-10 00:17:01.008282 | controller -> localhost | changed 2025-12-10 00:17:01.035296 | 2025-12-10 00:17:01.035465 | TASK [add-build-sshkey : Add back temp key] 2025-12-10 00:17:01.357757 | controller -> localhost | Identity added: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/1b454643945d4353942f07b5c1538397_id_ecdsa (zuul-build-sshkey) 2025-12-10 00:17:01.358057 | controller -> localhost | ok: Runtime: 0:00:00.013891 2025-12-10 00:17:01.367411 | 2025-12-10 00:17:01.367500 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-10 00:17:01.574847 | controller | ok 2025-12-10 00:17:01.582781 | 2025-12-10 00:17:01.582867 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-10 00:17:01.629112 | controller | skipping: Conditional result was False 2025-12-10 00:17:01.659485 | 2025-12-10 00:17:01.659660 | TASK [include_role : remove-zuul-sshkey] 2025-12-10 00:17:01.686033 | controller | skipping: Conditional result was False 2025-12-10 00:17:01.702328 | 2025-12-10 00:17:01.702669 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-10 00:17:01.950305 | controller | ok: "logs" 2025-12-10 00:17:01.950818 | controller | ok: All items complete 2025-12-10 00:17:01.950887 | 2025-12-10 00:17:02.152270 | controller | ok: "artifacts" 2025-12-10 00:17:02.343888 | controller | ok: "docs" 2025-12-10 00:17:02.362136 | 2025-12-10 00:17:02.362286 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-10 00:17:02.610904 | controller | changed: "logs" 2025-12-10 00:17:02.824551 | controller | changed: "artifacts" 2025-12-10 00:17:03.018918 | controller | changed: "docs" 2025-12-10 00:17:03.048488 | 2025-12-10 00:17:03.048584 | PLAY RECAP 2025-12-10 00:17:03.048629 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-10 00:17:03.048654 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-10 00:17:03.048671 | 2025-12-10 00:17:03.164804 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-10 00:17:03.165667 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-10 00:17:03.830396 | 2025-12-10 00:17:03.830532 | PLAY [all] 2025-12-10 00:17:03.853393 | 2025-12-10 00:17:03.853515 | TASK [Install binary dependencies] 2025-12-10 00:17:03.925357 | controller | ok 2025-12-10 00:17:03.950600 | 2025-12-10 00:17:03.950746 | TASK [bindep : Include find tasks] 2025-12-10 00:17:03.990962 | controller | ok 2025-12-10 00:17:03.999238 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-10 00:17:04.005494 | 2025-12-10 00:17:04.005560 | TASK [bindep : Look for bindep.txt] 2025-12-10 00:17:04.358385 | controller | ok 2025-12-10 00:17:04.373131 | 2025-12-10 00:17:04.373326 | TASK [bindep : Define bindep_file fact] 2025-12-10 00:17:04.401272 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.416005 | 2025-12-10 00:17:04.416189 | TASK [bindep : Look for other-requirements.txt] 2025-12-10 00:17:04.637036 | controller | ok 2025-12-10 00:17:04.647962 | 2025-12-10 00:17:04.648127 | TASK [bindep : Define bindep_file fact] 2025-12-10 00:17:04.686226 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.694595 | 2025-12-10 00:17:04.694712 | TASK [bindep : Look for bindep fallback file] 2025-12-10 00:17:04.730620 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.740340 | 2025-12-10 00:17:04.740477 | TASK [bindep : Define bindep_file fact] 2025-12-10 00:17:04.770925 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.779385 | 2025-12-10 00:17:04.779487 | TASK [bindep : Include bindep tasks] 2025-12-10 00:17:04.804871 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.813478 | 2025-12-10 00:17:04.813609 | TASK [bindep : Include install tasks] 2025-12-10 00:17:04.839406 | controller | skipping: Conditional result was False 2025-12-10 00:17:04.847411 | 2025-12-10 00:17:04.847512 | LOOP [bindep : Include package tasks] 2025-12-10 00:17:04.907667 | 2025-12-10 00:17:04.907845 | TASK [Run test-setup role] 2025-12-10 00:17:04.931147 | controller | ok 2025-12-10 00:17:04.955820 | 2025-12-10 00:17:04.955978 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-10 00:17:05.182322 | controller | ok 2025-12-10 00:17:05.200790 | 2025-12-10 00:17:05.200905 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-10 00:17:05.745321 | controller | skipping: Conditional result was False 2025-12-10 00:17:05.783860 | 2025-12-10 00:17:05.783957 | PLAY RECAP 2025-12-10 00:17:05.784015 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-10 00:17:05.784050 | 2025-12-10 00:17:05.885307 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-10 00:17:05.886157 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-10 00:17:06.461550 | 2025-12-10 00:17:06.461673 | PLAY [controller] 2025-12-10 00:17:06.481519 | 2025-12-10 00:17:06.481595 | TASK [Create the /root directory] 2025-12-10 00:17:06.859922 | controller | ok 2025-12-10 00:17:06.882969 | 2025-12-10 00:17:06.883192 | TASK [Install glibc-langpack-en] 2025-12-10 00:17:10.912248 | controller | ok: Nothing to do 2025-12-10 00:17:10.918699 | 2025-12-10 00:17:10.918792 | TASK [Ensure controller directory exists] 2025-12-10 00:17:11.145226 | controller | changed 2025-12-10 00:17:11.158920 | 2025-12-10 00:17:11.159090 | TASK [Install container runtime] 2025-12-10 00:17:11.223621 | controller | ok 2025-12-10 00:17:11.265913 | 2025-12-10 00:17:11.266065 | LOOP [ensure-podman : Find distribution installation] 2025-12-10 00:17:11.298162 | controller | ok: "/var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-10 00:17:11.307397 | controller | included: /var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-10 00:17:11.313886 | 2025-12-10 00:17:11.313956 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-10 00:18:17.230629 | controller | changed 2025-12-10 00:18:17.237661 | 2025-12-10 00:18:17.237754 | TASK [ensure-podman : Fetch podman version] 2025-12-10 00:18:17.758462 | controller | Client: Podman Engine 2025-12-10 00:18:17.758578 | controller | Version: 4.6.2 2025-12-10 00:18:17.758635 | controller | API Version: 4.6.2 2025-12-10 00:18:17.758677 | controller | Go Version: go1.19.12 2025-12-10 00:18:17.758734 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-10 00:18:17.758775 | controller | OS/Arch: linux/amd64 2025-12-10 00:18:18.269958 | controller | ok: Runtime: 0:00:00.190452 2025-12-10 00:18:18.285301 | 2025-12-10 00:18:18.285459 | TASK [ensure-podman : Print podman version installed] 2025-12-10 00:18:18.326462 | Podman version: Client: Podman Engine 2025-12-10 00:18:18.326812 | Version: 4.6.2 2025-12-10 00:18:18.326887 | API Version: 4.6.2 2025-12-10 00:18:18.326936 | Go Version: go1.19.12 2025-12-10 00:18:18.326980 | Built: Mon Aug 28 19:38:31 2023 2025-12-10 00:18:18.327028 | OS/Arch: linux/amd64 2025-12-10 00:18:18.340875 | 2025-12-10 00:18:18.341008 | TASK [ensure-podman : Validate podman engine] 2025-12-10 00:18:18.890089 | controller | skipping: Conditional result was False 2025-12-10 00:18:18.904105 | 2025-12-10 00:18:18.904240 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-10 00:18:18.931065 | controller | skipping: Conditional result was False 2025-12-10 00:18:18.955898 | 2025-12-10 00:18:18.956032 | TASK [Ensure python3.8 is present] 2025-12-10 00:18:18.982542 | controller | skipping: Conditional result was False 2025-12-10 00:18:18.989711 | 2025-12-10 00:18:18.989790 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-10 00:18:19.010087 | controller | ok 2025-12-10 00:18:19.028810 | 2025-12-10 00:18:19.028874 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-10 00:18:20.517434 | controller | ok: Nothing to do 2025-12-10 00:18:20.529873 | 2025-12-10 00:18:20.530012 | TASK [our-ensure-python : Also install python3-devel] 2025-12-10 00:20:29.307206 | controller | changed 2025-12-10 00:20:29.333958 | 2025-12-10 00:20:29.334098 | TASK [Run ensure-virtualenv role] 2025-12-10 00:20:29.365535 | controller | ok 2025-12-10 00:20:29.401013 | 2025-12-10 00:20:29.401165 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-10 00:20:29.660254 | controller | /usr/bin/virtualenv 2025-12-10 00:20:29.967268 | controller | ok: Runtime: 0:00:00.004864 2025-12-10 00:20:29.980001 | 2025-12-10 00:20:29.980145 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-10 00:20:30.016414 | controller | skipping: Conditional result was False 2025-12-10 00:20:30.016982 | controller | ok: All items complete 2025-12-10 00:20:30.017065 | 2025-12-10 00:20:30.044233 | 2025-12-10 00:20:30.044414 | TASK [Find the full path of the Python interpreter] 2025-12-10 00:20:30.285927 | controller | /usr/bin/python3 2025-12-10 00:20:30.589598 | controller | ok 2025-12-10 00:20:30.601654 | 2025-12-10 00:20:30.601846 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-10 00:20:31.622407 | controller | created virtual environment CPython3.11.0.final.0-64 in 532ms 2025-12-10 00:20:31.646092 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-10 00:20:31.646544 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-12-10 00:20:31.646812 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-10 00:20:31.647074 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-10 00:20:31.693700 | controller | changed 2025-12-10 00:20:31.706358 | 2025-12-10 00:20:31.706502 | TASK [Set selinux package] 2025-12-10 00:20:31.745576 | controller | ok 2025-12-10 00:20:31.757109 | 2025-12-10 00:20:31.757240 | TASK [Set selinux package (Fedora)] 2025-12-10 00:20:31.801122 | controller | ok 2025-12-10 00:20:31.806417 | 2025-12-10 00:20:31.806483 | TASK [Install selinux into virtualenv] 2025-12-10 00:20:43.247423 | controller | Collecting selinux-please-lie-to-me 2025-12-10 00:20:55.506304 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-10 00:20:55.842318 | controller | Collecting setuptools<50.0.0 2025-12-10 00:20:55.848917 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-10 00:20:55.890735 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.0 MB/s eta 0:00:00 2025-12-10 00:20:55.971447 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-10 00:20:55.971549 | controller | Attempting uninstall: setuptools 2025-12-10 00:20:55.973956 | controller | Found existing installation: setuptools 62.6.0 2025-12-10 00:20:56.032479 | controller | Uninstalling setuptools-62.6.0: 2025-12-10 00:20:56.040347 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-10 00:20:56.403844 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-10 00:21:07.880291 | controller | 2025-12-10 00:21:07.964222 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-10 00:21:07.964280 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-10 00:21:08.373574 | controller | ok: Runtime: 0:00:35.927657 2025-12-10 00:21:08.386166 | 2025-12-10 00:21:08.386321 | TASK [Install pytest-forked into virtualenv] 2025-12-10 00:21:20.118910 | controller | Collecting pytest-forked 2025-12-10 00:21:32.432937 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-10 00:21:32.475788 | controller | Collecting py 2025-12-10 00:21:32.481664 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-10 00:21:32.502770 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.3 MB/s eta 0:00:00 2025-12-10 00:21:32.606206 | controller | Collecting pytest>=3.10 2025-12-10 00:21:32.611848 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-10 00:21:32.626784 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 30.7 MB/s eta 0:00:00 2025-12-10 00:21:32.666073 | controller | Collecting iniconfig>=1.0.1 2025-12-10 00:21:32.669919 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-10 00:21:32.711868 | controller | Collecting packaging>=22 2025-12-10 00:21:32.714867 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-10 00:21:32.729039 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.4 MB/s eta 0:00:00 2025-12-10 00:21:32.764866 | controller | Collecting pluggy<2,>=1.5 2025-12-10 00:21:32.769135 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-10 00:21:32.816451 | controller | Collecting pygments>=2.7.2 2025-12-10 00:21:32.821101 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-10 00:21:32.845449 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 55.0 MB/s eta 0:00:00 2025-12-10 00:21:32.913232 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-10 00:21:33.948714 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-10 00:21:33.957560 | controller | 2025-12-10 00:21:34.029125 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-10 00:21:34.029178 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-10 00:21:34.459206 | controller | ok: Runtime: 0:00:25.399751 2025-12-10 00:21:34.471689 | 2025-12-10 00:21:34.472457 | TASK [Update pip] 2025-12-10 00:21:35.015224 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-10 00:21:45.389266 | controller | Collecting pip 2025-12-10 00:21:57.586675 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-10 00:21:57.655810 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 27.8 MB/s eta 0:00:00 2025-12-10 00:21:57.718737 | controller | Installing collected packages: pip 2025-12-10 00:21:57.718950 | controller | Attempting uninstall: pip 2025-12-10 00:21:57.721121 | controller | Found existing installation: pip 22.2.2 2025-12-10 00:21:57.863486 | controller | Uninstalling pip-22.2.2: 2025-12-10 00:21:57.878480 | controller | Successfully uninstalled pip-22.2.2 2025-12-10 00:21:58.674266 | controller | Successfully installed pip-25.3 2025-12-10 00:21:59.043094 | controller | ok: Runtime: 0:00:24.031304 2025-12-10 00:21:59.058066 | 2025-12-10 00:21:59.058270 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-10 00:21:59.290848 | controller | changed 2025-12-10 00:21:59.301395 | 2025-12-10 00:21:59.301518 | TASK [Install ansible into virtualenv] 2025-12-10 00:21:59.832486 | controller | Processing ./src/github.com/ansible/ansible 2025-12-10 00:21:59.835993 | controller | Installing build dependencies: started 2025-12-10 00:22:22.557766 | controller | Installing build dependencies: finished with status 'done' 2025-12-10 00:22:22.558888 | controller | Getting requirements to build wheel: started 2025-12-10 00:22:23.314085 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-10 00:22:23.315083 | controller | Preparing metadata (pyproject.toml): started 2025-12-10 00:22:23.790759 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-10 00:22:23.795978 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-12-10 00:22:23.799817 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-10 00:22:24.365154 | controller | ERROR 2025-12-10 00:22:24.365496 | controller | { 2025-12-10 00:22:24.365558 | controller | "delta": "0:00:24.317350", 2025-12-10 00:22:24.365600 | controller | "end": "2025-12-10 00:22:23.863157", 2025-12-10 00:22:24.365636 | controller | "msg": "non-zero return code", 2025-12-10 00:22:24.365689 | controller | "rc": 1, 2025-12-10 00:22:24.365756 | controller | "start": "2025-12-10 00:21:59.545807" 2025-12-10 00:22:24.365801 | controller | } failure 2025-12-10 00:22:24.368627 | 2025-12-10 00:22:24.368758 | PLAY RECAP 2025-12-10 00:22:24.368848 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-10 00:22:24.368892 | 2025-12-10 00:22:24.492196 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-10 00:22:24.493280 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-10 00:22:25.045508 | 2025-12-10 00:22:25.045618 | PLAY [all] 2025-12-10 00:22:25.066187 | 2025-12-10 00:22:25.066269 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-10 00:22:25.327361 | controller | changed: non-zero return code 2025-12-10 00:22:25.339616 | 2025-12-10 00:22:25.339802 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-10 00:22:25.357787 | controller | skipping: Conditional result was False 2025-12-10 00:22:25.371190 | 2025-12-10 00:22:25.371344 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-10 00:22:25.421637 | 2025-12-10 00:22:25.421917 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-10 00:22:25.461547 | 2025-12-10 00:22:25.461832 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-10 00:22:25.489057 | controller | skipping: Conditional result was False 2025-12-10 00:22:25.505569 | 2025-12-10 00:22:25.505706 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-10 00:22:25.555235 | 2025-12-10 00:22:25.555484 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-10 00:22:25.581919 | controller | skipping: Conditional result was False 2025-12-10 00:22:25.594705 | 2025-12-10 00:22:25.594872 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-10 00:22:25.621999 | controller | skipping: Conditional result was False 2025-12-10 00:22:25.634684 | 2025-12-10 00:22:25.634852 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-10 00:22:25.651755 | controller | skipping: Conditional result was False 2025-12-10 00:22:25.697270 | 2025-12-10 00:22:25.697365 | PLAY RECAP 2025-12-10 00:22:25.697419 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-10 00:22:25.697445 | 2025-12-10 00:22:25.798993 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-10 00:22:25.800135 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-10 00:22:26.360864 | 2025-12-10 00:22:26.360978 | PLAY [all:!appliance*] 2025-12-10 00:22:26.382229 | 2025-12-10 00:22:26.382308 | TASK [unregister the node] 2025-12-10 00:22:26.913436 | controller | skipping: Conditional result was False 2025-12-10 00:22:26.920095 | 2025-12-10 00:22:26.920180 | TASK [include_role : fetch-output] 2025-12-10 00:22:26.959892 | controller | ok 2025-12-10 00:22:26.979454 | 2025-12-10 00:22:26.979524 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-10 00:22:27.044189 | controller | skipping: Conditional result was False 2025-12-10 00:22:27.050539 | 2025-12-10 00:22:27.050608 | TASK [fetch-output : Set log path for single node] 2025-12-10 00:22:27.090179 | controller | ok 2025-12-10 00:22:27.095604 | 2025-12-10 00:22:27.095665 | LOOP [fetch-output : Ensure local output dirs] 2025-12-10 00:22:27.502689 | controller -> localhost | ok: "/var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/logs" 2025-12-10 00:22:27.757969 | controller -> localhost | changed: "/var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/artifacts" 2025-12-10 00:22:27.970913 | controller -> localhost | changed: "/var/lib/zuul/builds/1b454643945d4353942f07b5c1538397/work/docs" 2025-12-10 00:22:27.979430 | 2025-12-10 00:22:27.979500 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-10 00:22:28.593397 | controller | changed: 2025-12-10 00:22:28.593961 | controller | .d..t...... ./ 2025-12-10 00:22:28.594041 | controller | cd+++++++++ controller/ 2025-12-10 00:22:28.594118 | controller | changed: All items complete 2025-12-10 00:22:28.594161 | 2025-12-10 00:22:29.113570 | controller | changed: .d..t...... ./ 2025-12-10 00:22:29.634277 | controller | changed: .d..t...... ./ 2025-12-10 00:22:29.647012 | 2025-12-10 00:22:29.647091 | TASK [include_role : fetch-output-openshift] 2025-12-10 00:22:29.671070 | controller | skipping: Conditional result was False 2025-12-10 00:22:29.677393 | 2025-12-10 00:22:29.677462 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-10 00:22:29.721106 | controller | skipping: Conditional result was False 2025-12-10 00:22:29.733404 | controller | skipping: Conditional result was False 2025-12-10 00:22:29.768690 | 2025-12-10 00:22:29.768813 | PLAY [localhost] 2025-12-10 00:22:29.780703 | 2025-12-10 00:22:29.780797 | TASK [Run Zuul manifest role] 2025-12-10 00:22:29.798898 | localhost | ok 2025-12-10 00:22:29.812277 | 2025-12-10 00:22:29.812355 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-10 00:22:30.219803 | localhost | changed 2025-12-10 00:22:30.226755 | 2025-12-10 00:22:30.226855 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-10 00:22:30.261011 | localhost | ok 2025-12-10 00:22:30.273201 | 2025-12-10 00:22:30.273302 | TASK [Set zuul-log-path fact] 2025-12-10 00:22:30.295294 | localhost | ok 2025-12-10 00:22:30.316503 | 2025-12-10 00:22:30.316644 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-10 00:22:30.348403 | localhost | ok 2025-12-10 00:22:30.360721 | 2025-12-10 00:22:30.360851 | LOOP [Run upload-logs-swift role] 2025-12-10 00:22:30.398921 | localhost | Output suppressed because no_log was given 2025-12-10 00:22:30.434999 | 2025-12-10 00:22:30.435098 | TASK [Set zuul-log-path fact] 2025-12-10 00:22:30.470701 | localhost | skipping: Conditional result was False 2025-12-10 00:22:30.477442 | 2025-12-10 00:22:30.477555 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-10 00:22:30.937060 | localhost -> localhost | ok: Runtime: 0:00:00.008674 2025-12-10 00:22:30.974194 | 2025-12-10 00:22:30.974410 | TASK [upload-logs-swift : Upload logs to swift]