2025-12-20 00:14:36.809554 | Job console starting... 2025-12-20 00:14:36.821453 | Updating repositories 2025-12-20 00:14:36.941707 | Preparing job workspace 2025-12-20 00:14:40.696248 | Running Ansible setup... 2025-12-20 00:14:48.991766 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-20 00:14:49.725345 | 2025-12-20 00:14:49.725746 | PLAY [localhost] 2025-12-20 00:14:49.735554 | 2025-12-20 00:14:49.735882 | TASK [Gathering Facts] 2025-12-20 00:14:50.707429 | localhost | ok 2025-12-20 00:14:50.736442 | 2025-12-20 00:14:50.736572 | TASK [Setup log path fact] 2025-12-20 00:14:50.754777 | localhost | ok 2025-12-20 00:14:50.767521 | 2025-12-20 00:14:50.767603 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-20 00:14:50.786098 | localhost | ok 2025-12-20 00:14:50.794927 | 2025-12-20 00:14:50.795051 | TASK [emit-job-header : Print job information] 2025-12-20 00:14:50.833419 | # Job Information 2025-12-20 00:14:50.833584 | Ansible Version: 2.15.12 2025-12-20 00:14:50.833616 | Job: ansible-test-sanity-docker-devel 2025-12-20 00:14:50.833637 | Pipeline: periodic 2025-12-20 00:14:50.833656 | Executor: ze03.softwarefactory-project.io 2025-12-20 00:14:50.833674 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-20 00:14:50.833698 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/75a/ansible/75a542eb7e4f40b7873c9309ec49c222/ 2025-12-20 00:14:50.833718 | Event ID: e90b2a34aa9b47e1bd166d0e5d504958 2025-12-20 00:14:50.837499 | 2025-12-20 00:14:50.837565 | LOOP [emit-job-header : Print node information] 2025-12-20 00:14:50.939535 | localhost | ok: 2025-12-20 00:14:50.939754 | localhost | # Node Information 2025-12-20 00:14:50.939790 | localhost | Inventory Hostname: controller 2025-12-20 00:14:50.939811 | localhost | Hostname: np0005567568 2025-12-20 00:14:50.939831 | localhost | Username: zuul 2025-12-20 00:14:50.939856 | localhost | Distro: Fedora 37 2025-12-20 00:14:50.939960 | localhost | Provider: ansible-vexxhost-ams1 2025-12-20 00:14:50.939985 | localhost | Region: ams1 2025-12-20 00:14:50.940003 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-20 00:14:50.940021 | localhost | Product Name: OpenStack Nova 2025-12-20 00:14:50.940038 | localhost | Interface IP: 38.129.16.99 2025-12-20 00:14:50.950219 | 2025-12-20 00:14:50.950306 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-20 00:14:51.342376 | localhost -> localhost | changed 2025-12-20 00:14:51.352280 | 2025-12-20 00:14:51.352447 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-20 00:14:52.314448 | localhost -> localhost | changed 2025-12-20 00:14:52.347355 | 2025-12-20 00:14:52.347486 | PLAY [all:!appliance*] 2025-12-20 00:14:52.372634 | 2025-12-20 00:14:52.372780 | TASK [include_role : start-zuul-console] 2025-12-20 00:14:52.399029 | controller | ok 2025-12-20 00:14:52.420546 | 2025-12-20 00:14:52.420665 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-20 00:14:53.460219 | controller | ok 2025-12-20 00:14:53.492044 | 2025-12-20 00:14:53.492199 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-20 00:14:56.150317 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-20 00:14:56.179118 | 2025-12-20 00:14:56.179297 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-20 00:14:56.546474 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.556696 | 2025-12-20 00:14:56.556920 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-20 00:14:56.582754 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.593053 | 2025-12-20 00:14:56.593182 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-20 00:14:56.620354 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.629095 | 2025-12-20 00:14:56.629258 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-20 00:14:56.656078 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.665281 | 2025-12-20 00:14:56.665400 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-20 00:14:56.690951 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.699153 | 2025-12-20 00:14:56.699376 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-20 00:14:56.725907 | controller | skipping: Conditional result was False 2025-12-20 00:14:56.741157 | 2025-12-20 00:14:56.741315 | TASK [Disable Fedora Modular] 2025-12-20 00:14:57.922288 | controller | changed 2025-12-20 00:14:57.941358 | 2025-12-20 00:14:57.941565 | TASK [Enable EPEL] 2025-12-20 00:14:57.969688 | controller | skipping: Conditional result was False 2025-12-20 00:14:57.979566 | 2025-12-20 00:14:57.979669 | TASK [Register the RHEL node] 2025-12-20 00:14:58.407502 | 2025-12-20 00:14:58.407837 | TASK [Show the subscription-manager status] 2025-12-20 00:14:58.772101 | controller | skipping: Conditional result was False 2025-12-20 00:14:58.780288 | 2025-12-20 00:14:58.780393 | TASK [Enable EPEL on RHEL] 2025-12-20 00:14:59.135080 | controller | skipping: Conditional result was False 2025-12-20 00:14:59.142726 | 2025-12-20 00:14:59.142868 | TASK [Install git and tox] 2025-12-20 00:17:06.116767 | controller | changed 2025-12-20 00:17:06.123494 | 2025-12-20 00:17:06.123612 | TASK [include_role : prepare-workspace] 2025-12-20 00:17:06.154288 | controller | ok 2025-12-20 00:17:06.179302 | 2025-12-20 00:17:06.179440 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-20 00:17:07.014663 | controller | ok 2025-12-20 00:17:07.035882 | 2025-12-20 00:17:07.036100 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-20 00:17:23.412172 | controller | Output suppressed because no_log was given 2025-12-20 00:17:23.423309 | 2025-12-20 00:17:23.423399 | TASK [include_role : prepare-workspace-openshift] 2025-12-20 00:17:23.447928 | controller | skipping: Conditional result was False 2025-12-20 00:17:23.477060 | 2025-12-20 00:17:23.477147 | PLAY [all:!appliance] 2025-12-20 00:17:23.495973 | 2025-12-20 00:17:23.496066 | TASK [Run add-build-sshkey role (RSA)] 2025-12-20 00:17:23.529309 | controller | ok 2025-12-20 00:17:23.553456 | 2025-12-20 00:17:23.553653 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-20 00:17:23.806312 | controller -> localhost | ok 2025-12-20 00:17:23.814436 | 2025-12-20 00:17:23.814539 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-20 00:17:23.846072 | controller | ok 2025-12-20 00:17:23.864649 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-20 00:17:23.874222 | 2025-12-20 00:17:23.874338 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-20 00:17:24.370062 | controller -> localhost | Generating public/private rsa key pair. 2025-12-20 00:17:24.370272 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_rsa. 2025-12-20 00:17:24.370306 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_rsa.pub. 2025-12-20 00:17:24.370328 | controller -> localhost | The key fingerprint is: 2025-12-20 00:17:24.370347 | controller -> localhost | SHA256:g5I3Z6rSjCKEpg35wdvRXVlszzhqxxdkMiYW33IDiU0 zuul-build-sshkey 2025-12-20 00:17:24.370365 | controller -> localhost | The key's randomart image is: 2025-12-20 00:17:24.370384 | controller -> localhost | +---[RSA 2048]----+ 2025-12-20 00:17:24.370401 | controller -> localhost | | .*E. | 2025-12-20 00:17:24.370419 | controller -> localhost | | +.Xoo | 2025-12-20 00:17:24.370437 | controller -> localhost | | . *oO+ | 2025-12-20 00:17:24.370454 | controller -> localhost | | . . o oo+. | 2025-12-20 00:17:24.370471 | controller -> localhost | |.o o.+.S. o . . | 2025-12-20 00:17:24.370498 | controller -> localhost | |+oo .o.=..o o . | 2025-12-20 00:17:24.370522 | controller -> localhost | |++ B .. . . . | 2025-12-20 00:17:24.370543 | controller -> localhost | |+ * +. | 2025-12-20 00:17:24.370561 | controller -> localhost | |.. .. | 2025-12-20 00:17:24.370581 | controller -> localhost | +----[SHA256]-----+ 2025-12-20 00:17:24.370631 | controller -> localhost | ok: Runtime: 0:00:00.093461 2025-12-20 00:17:24.378517 | 2025-12-20 00:17:24.378591 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-20 00:17:24.409283 | controller | ok 2025-12-20 00:17:24.420551 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-20 00:17:24.430967 | 2025-12-20 00:17:24.431078 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-20 00:17:24.455696 | controller | skipping: Conditional result was False 2025-12-20 00:17:24.463048 | 2025-12-20 00:17:24.463139 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-20 00:17:25.547680 | controller | changed 2025-12-20 00:17:25.556836 | 2025-12-20 00:17:25.557008 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-20 00:17:26.240934 | controller | ok 2025-12-20 00:17:26.256754 | 2025-12-20 00:17:26.256941 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-20 00:17:29.271417 | controller | changed 2025-12-20 00:17:29.280415 | 2025-12-20 00:17:29.280586 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-20 00:17:32.256496 | controller | changed 2025-12-20 00:17:32.264845 | 2025-12-20 00:17:32.264979 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-20 00:17:32.289357 | controller | skipping: Conditional result was False 2025-12-20 00:17:32.296972 | 2025-12-20 00:17:32.297067 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-20 00:17:32.740820 | controller -> localhost | changed 2025-12-20 00:17:32.754394 | 2025-12-20 00:17:32.754532 | TASK [add-build-sshkey : Add back temp key] 2025-12-20 00:17:33.056949 | controller -> localhost | Identity added: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_rsa (zuul-build-sshkey) 2025-12-20 00:17:33.057369 | controller -> localhost | ok: Runtime: 0:00:00.009348 2025-12-20 00:17:33.066753 | 2025-12-20 00:17:33.066853 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-20 00:17:34.065097 | controller | ok 2025-12-20 00:17:34.071964 | 2025-12-20 00:17:34.072067 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-20 00:17:34.101146 | controller | skipping: Conditional result was False 2025-12-20 00:17:34.121491 | 2025-12-20 00:17:34.121695 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-20 00:17:34.156938 | controller | ok 2025-12-20 00:17:34.175717 | 2025-12-20 00:17:34.175919 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-20 00:17:34.469869 | controller -> localhost | ok 2025-12-20 00:17:34.477061 | 2025-12-20 00:17:34.477137 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-20 00:17:34.507989 | controller | ok 2025-12-20 00:17:34.518958 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-20 00:17:34.526671 | 2025-12-20 00:17:34.526778 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-20 00:17:34.837086 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-20 00:17:34.837352 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_ecdsa. 2025-12-20 00:17:34.837413 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_ecdsa.pub. 2025-12-20 00:17:34.837474 | controller -> localhost | The key fingerprint is: 2025-12-20 00:17:34.837517 | controller -> localhost | SHA256:SdYmNuu4vDIbvZjCt8tqMjfRFYN1EJ/KYxXKrcJ5QKI zuul-build-sshkey 2025-12-20 00:17:34.837574 | controller -> localhost | The key's randomart image is: 2025-12-20 00:17:34.837604 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-20 00:17:34.837634 | controller -> localhost | | . .o+oo | 2025-12-20 00:17:34.837670 | controller -> localhost | | . o..o= + | 2025-12-20 00:17:34.837705 | controller -> localhost | |E . oo@ o | 2025-12-20 00:17:34.838028 | controller -> localhost | | . +.B * | 2025-12-20 00:17:34.838077 | controller -> localhost | | .+.B S | 2025-12-20 00:17:34.838107 | controller -> localhost | | . .= + | 2025-12-20 00:17:34.838134 | controller -> localhost | | . .. o . | 2025-12-20 00:17:34.838160 | controller -> localhost | |o *.+= o | 2025-12-20 00:17:34.838187 | controller -> localhost | | =.=B*=. | 2025-12-20 00:17:34.838214 | controller -> localhost | +----[SHA256]-----+ 2025-12-20 00:17:34.838293 | controller -> localhost | ok: Runtime: 0:00:00.020887 2025-12-20 00:17:34.847652 | 2025-12-20 00:17:34.847798 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-20 00:17:34.887707 | controller | ok 2025-12-20 00:17:34.898654 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-20 00:17:34.910000 | 2025-12-20 00:17:34.910104 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-20 00:17:34.934908 | controller | skipping: Conditional result was False 2025-12-20 00:17:34.945833 | 2025-12-20 00:17:34.946028 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-20 00:17:35.873187 | controller | changed 2025-12-20 00:17:35.884315 | 2025-12-20 00:17:35.884465 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-20 00:17:36.552751 | controller | ok 2025-12-20 00:17:36.560463 | 2025-12-20 00:17:36.560590 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-20 00:17:39.561489 | controller | changed 2025-12-20 00:17:39.568520 | 2025-12-20 00:17:39.568647 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-20 00:17:42.543025 | controller | changed 2025-12-20 00:17:42.551215 | 2025-12-20 00:17:42.551338 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-20 00:17:42.578939 | controller | skipping: Conditional result was False 2025-12-20 00:17:42.587213 | 2025-12-20 00:17:42.587343 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-20 00:17:42.859213 | controller -> localhost | changed 2025-12-20 00:17:42.878474 | 2025-12-20 00:17:42.878687 | TASK [add-build-sshkey : Add back temp key] 2025-12-20 00:17:43.181402 | controller -> localhost | Identity added: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/75a542eb7e4f40b7873c9309ec49c222_id_ecdsa (zuul-build-sshkey) 2025-12-20 00:17:43.181612 | controller -> localhost | ok: Runtime: 0:00:00.010851 2025-12-20 00:17:43.189559 | 2025-12-20 00:17:43.189713 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-20 00:17:43.883033 | controller | ok 2025-12-20 00:17:43.903242 | 2025-12-20 00:17:43.903371 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-20 00:17:43.964333 | controller | skipping: Conditional result was False 2025-12-20 00:17:43.976464 | 2025-12-20 00:17:43.976560 | TASK [include_role : remove-zuul-sshkey] 2025-12-20 00:17:44.012153 | controller | skipping: Conditional result was False 2025-12-20 00:17:44.019757 | 2025-12-20 00:17:44.019847 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-20 00:17:44.667487 | controller | ok: "logs" 2025-12-20 00:17:44.668274 | controller | ok: All items complete 2025-12-20 00:17:44.668360 | 2025-12-20 00:17:45.285153 | controller | ok: "artifacts" 2025-12-20 00:17:45.887307 | controller | ok: "docs" 2025-12-20 00:17:45.908265 | 2025-12-20 00:17:45.908390 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-20 00:17:46.581141 | controller | changed: "logs" 2025-12-20 00:17:47.224035 | controller | changed: "artifacts" 2025-12-20 00:17:47.849567 | controller | changed: "docs" 2025-12-20 00:17:47.890935 | 2025-12-20 00:17:47.891059 | PLAY RECAP 2025-12-20 00:17:47.891107 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-20 00:17:47.891132 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-20 00:17:47.891149 | 2025-12-20 00:17:48.008464 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-20 00:17:48.010120 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-20 00:17:48.646566 | 2025-12-20 00:17:48.646711 | PLAY [all] 2025-12-20 00:17:48.671996 | 2025-12-20 00:17:48.672212 | TASK [Install binary dependencies] 2025-12-20 00:17:48.745103 | controller | ok 2025-12-20 00:17:48.773826 | 2025-12-20 00:17:48.774018 | TASK [bindep : Include find tasks] 2025-12-20 00:17:48.808504 | controller | ok 2025-12-20 00:17:48.820901 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-20 00:17:48.832631 | 2025-12-20 00:17:48.832896 | TASK [bindep : Look for bindep.txt] 2025-12-20 00:17:49.823857 | controller | ok 2025-12-20 00:17:49.838526 | 2025-12-20 00:17:49.838816 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:17:49.866827 | controller | skipping: Conditional result was False 2025-12-20 00:17:49.881455 | 2025-12-20 00:17:49.881603 | TASK [bindep : Look for other-requirements.txt] 2025-12-20 00:17:50.547170 | controller | ok 2025-12-20 00:17:50.562586 | 2025-12-20 00:17:50.562854 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:17:50.590416 | controller | skipping: Conditional result was False 2025-12-20 00:17:50.598330 | 2025-12-20 00:17:50.598441 | TASK [bindep : Look for bindep fallback file] 2025-12-20 00:17:50.623573 | controller | skipping: Conditional result was False 2025-12-20 00:17:50.633846 | 2025-12-20 00:17:50.634010 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:17:50.660961 | controller | skipping: Conditional result was False 2025-12-20 00:17:50.669356 | 2025-12-20 00:17:50.669531 | TASK [bindep : Include bindep tasks] 2025-12-20 00:17:50.694652 | controller | skipping: Conditional result was False 2025-12-20 00:17:50.706089 | 2025-12-20 00:17:50.706263 | TASK [bindep : Include install tasks] 2025-12-20 00:17:50.731971 | controller | skipping: Conditional result was False 2025-12-20 00:17:50.740145 | 2025-12-20 00:17:50.740300 | LOOP [bindep : Include package tasks] 2025-12-20 00:17:50.802051 | 2025-12-20 00:17:50.802271 | TASK [Run test-setup role] 2025-12-20 00:17:50.823230 | controller | ok 2025-12-20 00:17:50.843815 | 2025-12-20 00:17:50.843949 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-20 00:17:51.456494 | controller | ok 2025-12-20 00:17:51.463264 | 2025-12-20 00:17:51.463342 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-20 00:17:51.819389 | controller | skipping: Conditional result was False 2025-12-20 00:17:51.855053 | 2025-12-20 00:17:51.855178 | PLAY RECAP 2025-12-20 00:17:51.855234 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-20 00:17:51.855263 | 2025-12-20 00:17:51.993834 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-20 00:17:51.995373 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-20 00:17:52.657532 | 2025-12-20 00:17:52.657704 | PLAY [controller] 2025-12-20 00:17:52.678540 | 2025-12-20 00:17:52.678626 | TASK [Create the /root directory] 2025-12-20 00:17:53.788271 | controller | ok 2025-12-20 00:17:53.801423 | 2025-12-20 00:17:53.801643 | TASK [Install glibc-langpack-en] 2025-12-20 00:18:02.383646 | controller | ok: Nothing to do 2025-12-20 00:18:02.394053 | 2025-12-20 00:18:02.394219 | TASK [Ensure controller directory exists] 2025-12-20 00:18:03.207673 | controller | changed 2025-12-20 00:18:03.219498 | 2025-12-20 00:18:03.219640 | TASK [Install container runtime] 2025-12-20 00:18:03.260154 | controller | ok 2025-12-20 00:18:03.298914 | 2025-12-20 00:18:03.299058 | LOOP [ensure-podman : Find distribution installation] 2025-12-20 00:18:03.323643 | controller | ok: "/var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-20 00:18:03.342200 | controller | included: /var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-20 00:18:03.349286 | 2025-12-20 00:18:03.349417 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-20 00:19:54.985233 | controller | changed 2025-12-20 00:19:54.992576 | 2025-12-20 00:19:54.992687 | TASK [ensure-podman : Fetch podman version] 2025-12-20 00:19:56.141432 | controller | Client: Podman Engine 2025-12-20 00:19:56.141541 | controller | Version: 4.6.2 2025-12-20 00:19:56.141587 | controller | API Version: 4.6.2 2025-12-20 00:19:56.141629 | controller | Go Version: go1.19.12 2025-12-20 00:19:56.141683 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-20 00:19:56.141726 | controller | OS/Arch: linux/amd64 2025-12-20 00:19:56.352340 | controller | ok: Runtime: 0:00:00.298845 2025-12-20 00:19:56.359334 | 2025-12-20 00:19:56.359454 | TASK [ensure-podman : Print podman version installed] 2025-12-20 00:19:56.384065 | Podman version: Client: Podman Engine 2025-12-20 00:19:56.384230 | Version: 4.6.2 2025-12-20 00:19:56.384271 | API Version: 4.6.2 2025-12-20 00:19:56.384309 | Go Version: go1.19.12 2025-12-20 00:19:56.384337 | Built: Mon Aug 28 19:38:31 2023 2025-12-20 00:19:56.384359 | OS/Arch: linux/amd64 2025-12-20 00:19:56.390408 | 2025-12-20 00:19:56.390502 | TASK [ensure-podman : Validate podman engine] 2025-12-20 00:19:56.742181 | controller | skipping: Conditional result was False 2025-12-20 00:19:56.759075 | 2025-12-20 00:19:56.759217 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-20 00:19:56.774287 | controller | skipping: Conditional result was False 2025-12-20 00:19:56.791388 | 2025-12-20 00:19:56.791529 | TASK [Ensure python3.8 is present] 2025-12-20 00:19:56.817020 | controller | skipping: Conditional result was False 2025-12-20 00:19:56.826898 | 2025-12-20 00:19:56.827097 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-20 00:19:56.851286 | controller | ok 2025-12-20 00:19:56.881778 | 2025-12-20 00:19:56.881928 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-20 00:20:00.176421 | controller | ok: Nothing to do 2025-12-20 00:20:00.189471 | 2025-12-20 00:20:00.189604 | TASK [our-ensure-python : Also install python3-devel] 2025-12-20 00:20:15.545957 | controller | changed 2025-12-20 00:20:15.559989 | 2025-12-20 00:20:15.560100 | TASK [Run ensure-virtualenv role] 2025-12-20 00:20:15.591822 | controller | ok 2025-12-20 00:20:15.613862 | 2025-12-20 00:20:15.614006 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-20 00:20:16.385901 | controller | /usr/bin/virtualenv 2025-12-20 00:20:16.967896 | controller | ok: Runtime: 0:00:00.004678 2025-12-20 00:20:16.975383 | 2025-12-20 00:20:16.975515 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-20 00:20:17.002548 | controller | skipping: Conditional result was False 2025-12-20 00:20:17.002905 | controller | ok: All items complete 2025-12-20 00:20:17.002939 | 2025-12-20 00:20:17.025162 | 2025-12-20 00:20:17.025269 | TASK [Find the full path of the Python interpreter] 2025-12-20 00:20:17.762485 | controller | /usr/bin/python3 2025-12-20 00:20:18.381674 | controller | ok 2025-12-20 00:20:18.395362 | 2025-12-20 00:20:18.395537 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-20 00:20:20.138523 | controller | created virtual environment CPython3.11.0.final.0-64 in 787ms 2025-12-20 00:20:20.181748 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-20 00:20:20.181803 | 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-20 00:20:20.181819 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-20 00:20:20.181839 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-20 00:20:20.779185 | controller | changed 2025-12-20 00:20:20.792977 | 2025-12-20 00:20:20.793112 | TASK [Set selinux package] 2025-12-20 00:20:20.832619 | controller | ok 2025-12-20 00:20:20.844212 | 2025-12-20 00:20:20.844372 | TASK [Set selinux package (Fedora)] 2025-12-20 00:20:20.905675 | controller | ok 2025-12-20 00:20:20.918876 | 2025-12-20 00:20:20.919024 | TASK [Install selinux into virtualenv] 2025-12-20 00:20:23.651414 | controller | Collecting selinux-please-lie-to-me 2025-12-20 00:20:23.715811 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-20 00:20:24.188249 | controller | Collecting setuptools<50.0.0 2025-12-20 00:20:24.194308 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-20 00:20:24.242946 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 18.1 MB/s eta 0:00:00 2025-12-20 00:20:24.354837 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-20 00:20:24.355052 | controller | Attempting uninstall: setuptools 2025-12-20 00:20:24.358624 | controller | Found existing installation: setuptools 62.6.0 2025-12-20 00:20:24.451932 | controller | Uninstalling setuptools-62.6.0: 2025-12-20 00:20:24.464571 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-20 00:20:25.094200 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-20 00:20:25.272033 | controller | 2025-12-20 00:20:25.520423 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-20 00:20:25.520471 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-20 00:20:25.792213 | controller | ok: Runtime: 0:00:03.850598 2025-12-20 00:20:25.800048 | 2025-12-20 00:20:25.800202 | TASK [Install pytest-forked into virtualenv] 2025-12-20 00:20:27.261838 | controller | Collecting pytest-forked 2025-12-20 00:20:27.320459 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-20 00:20:27.371299 | controller | Collecting py 2025-12-20 00:20:27.377171 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-20 00:20:27.406225 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.9 MB/s eta 0:00:00 2025-12-20 00:20:27.581618 | controller | Collecting pytest>=3.10 2025-12-20 00:20:27.586333 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-20 00:20:27.605580 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 24.1 MB/s eta 0:00:00 2025-12-20 00:20:27.654772 | controller | Collecting iniconfig>=1.0.1 2025-12-20 00:20:27.659898 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-20 00:20:27.724378 | controller | Collecting packaging>=22 2025-12-20 00:20:27.731777 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-20 00:20:27.740968 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.5 MB/s eta 0:00:00 2025-12-20 00:20:27.786544 | controller | Collecting pluggy<2,>=1.5 2025-12-20 00:20:27.792558 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-20 00:20:27.871160 | controller | Collecting pygments>=2.7.2 2025-12-20 00:20:27.878184 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-20 00:20:27.909117 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 46.9 MB/s eta 0:00:00 2025-12-20 00:20:28.030961 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-20 00:20:30.681073 | 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-20 00:20:30.701506 | controller | 2025-12-20 00:20:30.950961 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-20 00:20:30.951012 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-20 00:20:31.176502 | controller | ok: Runtime: 0:00:04.394284 2025-12-20 00:20:31.183418 | 2025-12-20 00:20:31.183497 | TASK [Update pip] 2025-12-20 00:20:32.450410 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-20 00:20:32.772697 | controller | Collecting pip 2025-12-20 00:20:32.853715 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-20 00:20:32.932714 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.1 MB/s eta 0:00:00 2025-12-20 00:20:33.031186 | controller | Installing collected packages: pip 2025-12-20 00:20:33.031415 | controller | Attempting uninstall: pip 2025-12-20 00:20:33.034627 | controller | Found existing installation: pip 22.2.2 2025-12-20 00:20:33.268401 | controller | Uninstalling pip-22.2.2: 2025-12-20 00:20:33.317809 | controller | Successfully uninstalled pip-22.2.2 2025-12-20 00:20:35.100675 | controller | Successfully installed pip-25.3 2025-12-20 00:20:35.548055 | controller | ok: Runtime: 0:00:03.369311 2025-12-20 00:20:35.562676 | 2025-12-20 00:20:35.562871 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-20 00:20:36.508136 | controller | changed 2025-12-20 00:20:36.518951 | 2025-12-20 00:20:36.519074 | TASK [Install ansible into virtualenv] 2025-12-20 00:20:37.983056 | controller | Processing ./src/github.com/ansible/ansible 2025-12-20 00:20:37.989415 | controller | Installing build dependencies: started 2025-12-20 00:20:40.092409 | controller | Installing build dependencies: finished with status 'done' 2025-12-20 00:20:40.100344 | controller | Getting requirements to build wheel: started 2025-12-20 00:20:41.776401 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-20 00:20:41.777496 | controller | Preparing metadata (pyproject.toml): started 2025-12-20 00:20:42.707614 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-20 00:20:42.713924 | 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-20 00:20:42.720873 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-20 00:20:43.445609 | controller | ERROR 2025-12-20 00:20:43.445947 | controller | { 2025-12-20 00:20:43.445983 | controller | "delta": "0:00:05.675132", 2025-12-20 00:20:43.446017 | controller | "end": "2025-12-20 00:20:42.968003", 2025-12-20 00:20:43.446038 | controller | "msg": "non-zero return code", 2025-12-20 00:20:43.446078 | controller | "rc": 1, 2025-12-20 00:20:43.446095 | controller | "start": "2025-12-20 00:20:37.292871" 2025-12-20 00:20:43.446111 | controller | } failure 2025-12-20 00:20:43.448548 | 2025-12-20 00:20:43.448613 | PLAY RECAP 2025-12-20 00:20:43.448676 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-20 00:20:43.448703 | 2025-12-20 00:20:43.672351 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-20 00:20:43.673571 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-20 00:20:44.307483 | 2025-12-20 00:20:44.307719 | PLAY [all] 2025-12-20 00:20:44.332528 | 2025-12-20 00:20:44.332668 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-20 00:20:46.181049 | controller | changed: non-zero return code 2025-12-20 00:20:46.189214 | 2025-12-20 00:20:46.189332 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-20 00:20:46.215681 | controller | skipping: Conditional result was False 2025-12-20 00:20:46.225412 | 2025-12-20 00:20:46.225557 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-20 00:20:46.265231 | 2025-12-20 00:20:46.265464 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-20 00:20:46.302670 | 2025-12-20 00:20:46.302993 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-20 00:20:46.329802 | controller | skipping: Conditional result was False 2025-12-20 00:20:46.340154 | 2025-12-20 00:20:46.340364 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-20 00:20:46.376549 | 2025-12-20 00:20:46.376820 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-20 00:20:46.403460 | controller | skipping: Conditional result was False 2025-12-20 00:20:46.412610 | 2025-12-20 00:20:46.412826 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-20 00:20:46.429705 | controller | skipping: Conditional result was False 2025-12-20 00:20:46.439234 | 2025-12-20 00:20:46.439377 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-20 00:20:46.465917 | controller | skipping: Conditional result was False 2025-12-20 00:20:46.504259 | 2025-12-20 00:20:46.504401 | PLAY RECAP 2025-12-20 00:20:46.504495 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-20 00:20:46.504525 | 2025-12-20 00:20:46.669531 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-20 00:20:46.670782 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-20 00:20:47.341713 | 2025-12-20 00:20:47.341872 | PLAY [all:!appliance*] 2025-12-20 00:20:47.363950 | 2025-12-20 00:20:47.364084 | TASK [unregister the node] 2025-12-20 00:20:47.721162 | controller | skipping: Conditional result was False 2025-12-20 00:20:47.731174 | 2025-12-20 00:20:47.731963 | TASK [include_role : fetch-output] 2025-12-20 00:20:47.767649 | controller | ok 2025-12-20 00:20:47.800334 | 2025-12-20 00:20:47.800491 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-20 00:20:47.878944 | controller | skipping: Conditional result was False 2025-12-20 00:20:47.889812 | 2025-12-20 00:20:47.889994 | TASK [fetch-output : Set log path for single node] 2025-12-20 00:20:47.935010 | controller | ok 2025-12-20 00:20:47.944323 | 2025-12-20 00:20:47.944426 | LOOP [fetch-output : Ensure local output dirs] 2025-12-20 00:20:48.369861 | controller -> localhost | ok: "/var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/logs" 2025-12-20 00:20:48.608103 | controller -> localhost | changed: "/var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/artifacts" 2025-12-20 00:20:48.841540 | controller -> localhost | changed: "/var/lib/zuul/builds/75a542eb7e4f40b7873c9309ec49c222/work/docs" 2025-12-20 00:20:48.871633 | 2025-12-20 00:20:48.871893 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-20 00:20:51.101164 | controller | changed: 2025-12-20 00:20:51.101820 | controller | .d..t...... ./ 2025-12-20 00:20:51.101921 | controller | cd+++++++++ controller/ 2025-12-20 00:20:51.102001 | controller | changed: All items complete 2025-12-20 00:20:51.102046 | 2025-12-20 00:20:53.135587 | controller | changed: .d..t...... ./ 2025-12-20 00:20:55.218980 | controller | changed: .d..t...... ./ 2025-12-20 00:20:55.241601 | 2025-12-20 00:20:55.241841 | TASK [include_role : fetch-output-openshift] 2025-12-20 00:20:55.268716 | controller | skipping: Conditional result was False 2025-12-20 00:20:55.277417 | 2025-12-20 00:20:55.277557 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-20 00:20:55.309766 | controller | skipping: Conditional result was False 2025-12-20 00:20:55.320787 | controller | skipping: Conditional result was False 2025-12-20 00:20:55.356460 | 2025-12-20 00:20:55.356610 | PLAY [localhost] 2025-12-20 00:20:55.371327 | 2025-12-20 00:20:55.371439 | TASK [Run Zuul manifest role] 2025-12-20 00:20:55.390292 | localhost | ok 2025-12-20 00:20:55.406017 | 2025-12-20 00:20:55.406169 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-20 00:20:55.772048 | localhost | changed 2025-12-20 00:20:55.776839 | 2025-12-20 00:20:55.776913 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-20 00:20:55.805370 | localhost | ok 2025-12-20 00:20:55.814925 | 2025-12-20 00:20:55.815027 | TASK [Set zuul-log-path fact] 2025-12-20 00:20:55.835546 | localhost | ok 2025-12-20 00:20:55.881117 | 2025-12-20 00:20:55.881263 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-20 00:20:55.910567 | localhost | ok 2025-12-20 00:20:55.919561 | 2025-12-20 00:20:55.919648 | LOOP [Run upload-logs-swift role] 2025-12-20 00:20:55.943584 | localhost | Output suppressed because no_log was given 2025-12-20 00:20:55.977915 | 2025-12-20 00:20:55.978073 | TASK [Set zuul-log-path fact] 2025-12-20 00:20:56.003916 | localhost | skipping: Conditional result was False 2025-12-20 00:20:56.012038 | 2025-12-20 00:20:56.012172 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-20 00:20:56.417266 | localhost -> localhost | ok: Runtime: 0:00:00.005835 2025-12-20 00:20:56.431292 | 2025-12-20 00:20:56.431525 | TASK [upload-logs-swift : Upload logs to swift]