2025-12-01 00:28:22.622494 | Job console starting... 2025-12-01 00:28:22.637403 | Updating repositories 2025-12-01 00:28:22.785329 | Preparing job workspace 2025-12-01 00:28:26.195202 | Running Ansible setup... 2025-12-01 00:28:33.643895 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-01 00:28:34.256463 | 2025-12-01 00:28:34.256572 | PLAY [localhost] 2025-12-01 00:28:34.264416 | 2025-12-01 00:28:34.264482 | TASK [Gathering Facts] 2025-12-01 00:28:35.207024 | localhost | ok 2025-12-01 00:28:35.220652 | 2025-12-01 00:28:35.220755 | TASK [Setup log path fact] 2025-12-01 00:28:35.239305 | localhost | ok 2025-12-01 00:28:35.251351 | 2025-12-01 00:28:35.251413 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-01 00:28:35.279846 | localhost | ok 2025-12-01 00:28:35.287992 | 2025-12-01 00:28:35.288067 | TASK [emit-job-header : Print job information] 2025-12-01 00:28:35.329338 | # Job Information 2025-12-01 00:28:35.329463 | Ansible Version: 2.15.12 2025-12-01 00:28:35.329494 | Job: ansible-test-sanity-docker-milestone 2025-12-01 00:28:35.329514 | Pipeline: periodic 2025-12-01 00:28:35.329532 | Executor: ze02.softwarefactory-project.io 2025-12-01 00:28:35.329549 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-01 00:28:35.329569 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/8e6/ansible/8e6df85f9e9c468bb3a9f296002d3eee/ 2025-12-01 00:28:35.329588 | Event ID: 7f239586727e4cf3b26e006c8a5b9dc9 2025-12-01 00:28:35.333316 | 2025-12-01 00:28:35.333377 | LOOP [emit-job-header : Print node information] 2025-12-01 00:28:35.435059 | localhost | ok: 2025-12-01 00:28:35.435488 | localhost | # Node Information 2025-12-01 00:28:35.435547 | localhost | Inventory Hostname: controller 2025-12-01 00:28:35.435589 | localhost | Hostname: np0005540487 2025-12-01 00:28:35.435630 | localhost | Username: zuul 2025-12-01 00:28:35.435713 | localhost | Distro: Fedora 37 2025-12-01 00:28:35.435765 | localhost | Provider: ansible-vexxhost-ams1 2025-12-01 00:28:35.435807 | localhost | Region: ams1 2025-12-01 00:28:35.435843 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-01 00:28:35.435879 | localhost | Product Name: OpenStack Nova 2025-12-01 00:28:35.435915 | localhost | Interface IP: 38.129.16.80 2025-12-01 00:28:35.456062 | 2025-12-01 00:28:35.456232 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-01 00:28:35.840108 | localhost -> localhost | changed 2025-12-01 00:28:35.851450 | 2025-12-01 00:28:35.851521 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-01 00:28:36.729115 | localhost -> localhost | changed 2025-12-01 00:28:36.748813 | 2025-12-01 00:28:36.748878 | PLAY [all:!appliance*] 2025-12-01 00:28:36.764623 | 2025-12-01 00:28:36.764719 | TASK [include_role : start-zuul-console] 2025-12-01 00:28:36.784187 | controller | ok 2025-12-01 00:28:36.797402 | 2025-12-01 00:28:36.797467 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-01 00:28:37.761443 | controller | ok 2025-12-01 00:28:37.785536 | 2025-12-01 00:28:37.785723 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-01 00:28:39.970638 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-01 00:28:39.984658 | 2025-12-01 00:28:39.984833 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-01 00:28:40.358951 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.372892 | 2025-12-01 00:28:40.373039 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-01 00:28:40.400647 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.416603 | 2025-12-01 00:28:40.416784 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-01 00:28:40.443229 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.457573 | 2025-12-01 00:28:40.457758 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-01 00:28:40.486062 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.494889 | 2025-12-01 00:28:40.494986 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-01 00:28:40.520368 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.529401 | 2025-12-01 00:28:40.529500 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-01 00:28:40.575583 | controller | skipping: Conditional result was False 2025-12-01 00:28:40.591625 | 2025-12-01 00:28:40.591758 | TASK [Disable Fedora Modular] 2025-12-01 00:28:41.600722 | controller | changed 2025-12-01 00:28:41.618445 | 2025-12-01 00:28:41.618634 | TASK [Enable EPEL] 2025-12-01 00:28:41.648802 | controller | skipping: Conditional result was False 2025-12-01 00:28:41.658443 | 2025-12-01 00:28:41.658538 | TASK [Register the RHEL node] 2025-12-01 00:28:42.065546 | 2025-12-01 00:28:42.065777 | TASK [Show the subscription-manager status] 2025-12-01 00:28:42.439342 | controller | skipping: Conditional result was False 2025-12-01 00:28:42.448303 | 2025-12-01 00:28:42.448394 | TASK [Enable EPEL on RHEL] 2025-12-01 00:28:42.824052 | controller | skipping: Conditional result was False 2025-12-01 00:28:42.832215 | 2025-12-01 00:28:42.832313 | TASK [Install git and tox] 2025-12-01 00:30:41.178925 | controller | changed 2025-12-01 00:30:41.192299 | 2025-12-01 00:30:41.192435 | TASK [include_role : prepare-workspace] 2025-12-01 00:30:41.245805 | controller | ok 2025-12-01 00:30:41.289867 | 2025-12-01 00:30:41.290048 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-01 00:30:42.130955 | controller | ok 2025-12-01 00:30:42.146307 | 2025-12-01 00:30:42.146493 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-01 00:30:57.325310 | controller | Output suppressed because no_log was given 2025-12-01 00:30:57.341614 | 2025-12-01 00:30:57.341715 | TASK [include_role : prepare-workspace-openshift] 2025-12-01 00:30:57.366981 | controller | skipping: Conditional result was False 2025-12-01 00:30:57.415185 | 2025-12-01 00:30:57.415279 | PLAY [all:!appliance] 2025-12-01 00:30:57.430756 | 2025-12-01 00:30:57.430813 | TASK [Run add-build-sshkey role (RSA)] 2025-12-01 00:30:57.451043 | controller | ok 2025-12-01 00:30:57.467700 | 2025-12-01 00:30:57.467770 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-01 00:30:57.694881 | controller -> localhost | ok 2025-12-01 00:30:57.702051 | 2025-12-01 00:30:57.702119 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-01 00:30:57.722916 | controller | ok 2025-12-01 00:30:57.739411 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-01 00:30:57.746652 | 2025-12-01 00:30:57.746738 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-01 00:30:58.125980 | controller -> localhost | Generating public/private rsa key pair. 2025-12-01 00:30:58.126192 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_rsa. 2025-12-01 00:30:58.126222 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_rsa.pub. 2025-12-01 00:30:58.126243 | controller -> localhost | The key fingerprint is: 2025-12-01 00:30:58.126263 | controller -> localhost | SHA256:V69FYMug9uOQ+ZADMUTiNDIL/wFgTDFaDTFoMHExq00 zuul-build-sshkey 2025-12-01 00:30:58.126282 | controller -> localhost | The key's randomart image is: 2025-12-01 00:30:58.126300 | controller -> localhost | +---[RSA 2048]----+ 2025-12-01 00:30:58.126318 | controller -> localhost | |XO&=+o= . o | 2025-12-01 00:30:58.126337 | controller -> localhost | |+O.@.o o . + o | 2025-12-01 00:30:58.126368 | controller -> localhost | |o E o . o + . | 2025-12-01 00:30:58.126389 | controller -> localhost | | + . . o = . o | 2025-12-01 00:30:58.126406 | controller -> localhost | |. . . S + o | 2025-12-01 00:30:58.126432 | controller -> localhost | | B . o | 2025-12-01 00:30:58.126456 | controller -> localhost | | o . | 2025-12-01 00:30:58.126474 | controller -> localhost | | | 2025-12-01 00:30:58.126492 | controller -> localhost | | | 2025-12-01 00:30:58.126513 | controller -> localhost | +----[SHA256]-----+ 2025-12-01 00:30:58.126566 | controller -> localhost | ok: Runtime: 0:00:00.046239 2025-12-01 00:30:58.133140 | 2025-12-01 00:30:58.133205 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-01 00:30:58.162395 | controller | ok 2025-12-01 00:30:58.172215 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-01 00:30:58.181755 | 2025-12-01 00:30:58.181831 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-01 00:30:58.205722 | controller | skipping: Conditional result was False 2025-12-01 00:30:58.212159 | 2025-12-01 00:30:58.212228 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-01 00:30:59.221753 | controller | changed 2025-12-01 00:30:59.234345 | 2025-12-01 00:30:59.234486 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-01 00:30:59.854748 | controller | ok 2025-12-01 00:30:59.867179 | 2025-12-01 00:30:59.867276 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-01 00:31:02.830924 | controller | changed 2025-12-01 00:31:02.838718 | 2025-12-01 00:31:02.838826 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-01 00:31:05.778114 | controller | changed 2025-12-01 00:31:05.790906 | 2025-12-01 00:31:05.791041 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-01 00:31:05.818141 | controller | skipping: Conditional result was False 2025-12-01 00:31:05.831390 | 2025-12-01 00:31:05.831527 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-01 00:31:06.243649 | controller -> localhost | changed 2025-12-01 00:31:06.255420 | 2025-12-01 00:31:06.255489 | TASK [add-build-sshkey : Add back temp key] 2025-12-01 00:31:06.562912 | controller -> localhost | Identity added: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_rsa (zuul-build-sshkey) 2025-12-01 00:31:06.563145 | controller -> localhost | ok: Runtime: 0:00:00.012524 2025-12-01 00:31:06.569643 | 2025-12-01 00:31:06.569727 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-01 00:31:07.448217 | controller | ok 2025-12-01 00:31:07.463327 | 2025-12-01 00:31:07.463483 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-01 00:31:07.503013 | controller | skipping: Conditional result was False 2025-12-01 00:31:07.532473 | 2025-12-01 00:31:07.532642 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-01 00:31:07.574689 | controller | ok 2025-12-01 00:31:07.603943 | 2025-12-01 00:31:07.604203 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-01 00:31:07.894280 | controller -> localhost | ok 2025-12-01 00:31:07.904095 | 2025-12-01 00:31:07.904187 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-01 00:31:07.951748 | controller | ok 2025-12-01 00:31:07.966687 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-01 00:31:07.975476 | 2025-12-01 00:31:07.975562 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-01 00:31:08.317023 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-01 00:31:08.317226 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_ecdsa. 2025-12-01 00:31:08.317254 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_ecdsa.pub. 2025-12-01 00:31:08.317282 | controller -> localhost | The key fingerprint is: 2025-12-01 00:31:08.317302 | controller -> localhost | SHA256:yooE9eGV3GNCwBQW7okwEKSMd3ELYo5Oogdlj8+kr74 zuul-build-sshkey 2025-12-01 00:31:08.317320 | controller -> localhost | The key's randomart image is: 2025-12-01 00:31:08.317337 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-01 00:31:08.317355 | controller -> localhost | |+o=oO+o | 2025-12-01 00:31:08.317372 | controller -> localhost | |=* *.* + | 2025-12-01 00:31:08.317389 | controller -> localhost | |Oo= * * + | 2025-12-01 00:31:08.317405 | controller -> localhost | |=* @ + o . | 2025-12-01 00:31:08.317421 | controller -> localhost | |o.+ B S | 2025-12-01 00:31:08.317437 | controller -> localhost | | o . . . | 2025-12-01 00:31:08.317453 | controller -> localhost | | . . o | 2025-12-01 00:31:08.317469 | controller -> localhost | | . o . | 2025-12-01 00:31:08.317485 | controller -> localhost | | .E.. | 2025-12-01 00:31:08.317501 | controller -> localhost | +----[SHA256]-----+ 2025-12-01 00:31:08.317549 | controller -> localhost | ok: Runtime: 0:00:00.013041 2025-12-01 00:31:08.324161 | 2025-12-01 00:31:08.324226 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-01 00:31:08.354284 | controller | ok 2025-12-01 00:31:08.362453 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-01 00:31:08.371096 | 2025-12-01 00:31:08.371159 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-01 00:31:08.394881 | controller | skipping: Conditional result was False 2025-12-01 00:31:08.401935 | 2025-12-01 00:31:08.402002 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-01 00:31:09.261135 | controller | changed 2025-12-01 00:31:09.274301 | 2025-12-01 00:31:09.274443 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-01 00:31:09.938557 | controller | ok 2025-12-01 00:31:09.946732 | 2025-12-01 00:31:09.946821 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-01 00:31:12.883952 | controller | changed 2025-12-01 00:31:12.896145 | 2025-12-01 00:31:12.896291 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-01 00:31:15.787783 | controller | changed 2025-12-01 00:31:15.795629 | 2025-12-01 00:31:15.795735 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-01 00:31:15.822236 | controller | skipping: Conditional result was False 2025-12-01 00:31:15.831830 | 2025-12-01 00:31:15.831917 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-01 00:31:16.102324 | controller -> localhost | changed 2025-12-01 00:31:16.117444 | 2025-12-01 00:31:16.117530 | TASK [add-build-sshkey : Add back temp key] 2025-12-01 00:31:16.408987 | controller -> localhost | Identity added: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/8e6df85f9e9c468bb3a9f296002d3eee_id_ecdsa (zuul-build-sshkey) 2025-12-01 00:31:16.409214 | controller -> localhost | ok: Runtime: 0:00:00.007561 2025-12-01 00:31:16.415511 | 2025-12-01 00:31:16.415570 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-01 00:31:17.089053 | controller | ok 2025-12-01 00:31:17.100935 | 2025-12-01 00:31:17.101094 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-01 00:31:17.138451 | controller | skipping: Conditional result was False 2025-12-01 00:31:17.162830 | 2025-12-01 00:31:17.162967 | TASK [include_role : remove-zuul-sshkey] 2025-12-01 00:31:17.190985 | controller | skipping: Conditional result was False 2025-12-01 00:31:17.206430 | 2025-12-01 00:31:17.206571 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-01 00:31:17.755701 | controller | ok: "logs" 2025-12-01 00:31:17.756557 | controller | ok: All items complete 2025-12-01 00:31:17.756636 | 2025-12-01 00:31:18.248360 | controller | ok: "artifacts" 2025-12-01 00:31:18.743848 | controller | ok: "docs" 2025-12-01 00:31:18.760874 | 2025-12-01 00:31:18.761098 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-01 00:31:19.297136 | controller | changed: "logs" 2025-12-01 00:31:19.791343 | controller | changed: "artifacts" 2025-12-01 00:31:20.286140 | controller | changed: "docs" 2025-12-01 00:31:20.356221 | 2025-12-01 00:31:20.356358 | PLAY RECAP 2025-12-01 00:31:20.356422 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-01 00:31:20.356458 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-01 00:31:20.356483 | 2025-12-01 00:31:20.476072 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-01 00:31:20.477198 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-01 00:31:21.065044 | 2025-12-01 00:31:21.065149 | PLAY [all] 2025-12-01 00:31:21.086610 | 2025-12-01 00:31:21.086704 | TASK [Install binary dependencies] 2025-12-01 00:31:21.158336 | controller | ok 2025-12-01 00:31:21.184863 | 2025-12-01 00:31:21.184966 | TASK [bindep : Include find tasks] 2025-12-01 00:31:21.216843 | controller | ok 2025-12-01 00:31:21.227569 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-01 00:31:21.237542 | 2025-12-01 00:31:21.237629 | TASK [bindep : Look for bindep.txt] 2025-12-01 00:31:22.150061 | controller | ok 2025-12-01 00:31:22.156210 | 2025-12-01 00:31:22.156295 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:31:22.180756 | controller | skipping: Conditional result was False 2025-12-01 00:31:22.186685 | 2025-12-01 00:31:22.186749 | TASK [bindep : Look for other-requirements.txt] 2025-12-01 00:31:22.815260 | controller | ok 2025-12-01 00:31:22.829286 | 2025-12-01 00:31:22.829471 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:31:22.865644 | controller | skipping: Conditional result was False 2025-12-01 00:31:22.889003 | 2025-12-01 00:31:22.889137 | TASK [bindep : Look for bindep fallback file] 2025-12-01 00:31:22.929122 | controller | skipping: Conditional result was False 2025-12-01 00:31:22.943003 | 2025-12-01 00:31:22.943181 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:31:22.973166 | controller | skipping: Conditional result was False 2025-12-01 00:31:22.982081 | 2025-12-01 00:31:22.982168 | TASK [bindep : Include bindep tasks] 2025-12-01 00:31:23.013938 | controller | skipping: Conditional result was False 2025-12-01 00:31:23.022347 | 2025-12-01 00:31:23.022435 | TASK [bindep : Include install tasks] 2025-12-01 00:31:23.047188 | controller | skipping: Conditional result was False 2025-12-01 00:31:23.055338 | 2025-12-01 00:31:23.055431 | LOOP [bindep : Include package tasks] 2025-12-01 00:31:23.140659 | 2025-12-01 00:31:23.140840 | TASK [Run test-setup role] 2025-12-01 00:31:23.162260 | controller | ok 2025-12-01 00:31:23.186845 | 2025-12-01 00:31:23.186938 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-01 00:31:23.855578 | controller | ok 2025-12-01 00:31:23.868521 | 2025-12-01 00:31:23.868652 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-01 00:31:24.242912 | controller | skipping: Conditional result was False 2025-12-01 00:31:24.301705 | 2025-12-01 00:31:24.301871 | PLAY RECAP 2025-12-01 00:31:24.301953 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-01 00:31:24.301997 | 2025-12-01 00:31:24.443102 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-01 00:31:24.444792 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-01 00:31:25.060106 | 2025-12-01 00:31:25.060219 | PLAY [controller] 2025-12-01 00:31:25.079967 | 2025-12-01 00:31:25.080040 | TASK [Create the /root directory] 2025-12-01 00:31:26.053449 | controller | ok 2025-12-01 00:31:26.064758 | 2025-12-01 00:31:26.064832 | TASK [Install glibc-langpack-en] 2025-12-01 00:31:33.020318 | controller | ok: Nothing to do 2025-12-01 00:31:33.032807 | 2025-12-01 00:31:33.032947 | TASK [Ensure controller directory exists] 2025-12-01 00:31:33.807985 | controller | changed 2025-12-01 00:31:33.820646 | 2025-12-01 00:31:33.820829 | TASK [Install container runtime] 2025-12-01 00:31:33.891343 | controller | ok 2025-12-01 00:31:33.950763 | 2025-12-01 00:31:33.950895 | LOOP [ensure-podman : Find distribution installation] 2025-12-01 00:31:33.998928 | controller | ok: "/var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-01 00:31:34.007167 | controller | included: /var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-01 00:31:34.013706 | 2025-12-01 00:31:34.013775 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-01 00:33:20.783297 | controller | changed 2025-12-01 00:33:20.803938 | 2025-12-01 00:33:20.804072 | TASK [ensure-podman : Fetch podman version] 2025-12-01 00:33:21.892992 | controller | Client: Podman Engine 2025-12-01 00:33:21.936975 | controller | Version: 4.6.2 2025-12-01 00:33:21.937039 | controller | API Version: 4.6.2 2025-12-01 00:33:21.937048 | controller | Go Version: go1.19.12 2025-12-01 00:33:21.937067 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-01 00:33:21.937075 | controller | OS/Arch: linux/amd64 2025-12-01 00:33:22.174622 | controller | ok: Runtime: 0:00:00.281019 2025-12-01 00:33:22.187700 | 2025-12-01 00:33:22.187830 | TASK [ensure-podman : Print podman version installed] 2025-12-01 00:33:22.226120 | Podman version: Client: Podman Engine 2025-12-01 00:33:22.226338 | Version: 4.6.2 2025-12-01 00:33:22.226396 | API Version: 4.6.2 2025-12-01 00:33:22.226439 | Go Version: go1.19.12 2025-12-01 00:33:22.226479 | Built: Mon Aug 28 19:38:31 2023 2025-12-01 00:33:22.226518 | OS/Arch: linux/amd64 2025-12-01 00:33:22.238523 | 2025-12-01 00:33:22.238648 | TASK [ensure-podman : Validate podman engine] 2025-12-01 00:33:22.611369 | controller | skipping: Conditional result was False 2025-12-01 00:33:22.620006 | 2025-12-01 00:33:22.620090 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-01 00:33:22.644606 | controller | skipping: Conditional result was False 2025-12-01 00:33:22.659250 | 2025-12-01 00:33:22.659331 | TASK [Ensure python3.8 is present] 2025-12-01 00:33:22.683940 | controller | skipping: Conditional result was False 2025-12-01 00:33:22.692001 | 2025-12-01 00:33:22.692080 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-01 00:33:22.715538 | controller | ok 2025-12-01 00:33:22.740362 | 2025-12-01 00:33:22.740449 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-01 00:33:26.103997 | controller | ok: Nothing to do 2025-12-01 00:33:26.116095 | 2025-12-01 00:33:26.116225 | TASK [our-ensure-python : Also install python3-devel] 2025-12-01 00:33:41.219885 | controller | changed 2025-12-01 00:33:41.232603 | 2025-12-01 00:33:41.232689 | TASK [Run ensure-virtualenv role] 2025-12-01 00:33:41.262851 | controller | ok 2025-12-01 00:33:41.285150 | 2025-12-01 00:33:41.285246 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-01 00:33:42.031590 | controller | /usr/bin/virtualenv 2025-12-01 00:33:42.174799 | controller | ok: Runtime: 0:00:00.006374 2025-12-01 00:33:42.187333 | 2025-12-01 00:33:42.187466 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-01 00:33:42.221650 | controller | skipping: Conditional result was False 2025-12-01 00:33:42.222045 | controller | ok: All items complete 2025-12-01 00:33:42.222078 | 2025-12-01 00:33:42.248974 | 2025-12-01 00:33:42.249131 | TASK [Find the full path of the Python interpreter] 2025-12-01 00:33:42.844831 | controller | /usr/bin/python3 2025-12-01 00:33:43.116065 | controller | ok 2025-12-01 00:33:43.128498 | 2025-12-01 00:33:43.128652 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-01 00:33:44.702852 | controller | created virtual environment CPython3.11.0.final.0-64 in 804ms 2025-12-01 00:33:44.746702 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-01 00:33:44.746782 | 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-01 00:33:44.746801 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-01 00:33:44.746823 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-01 00:33:45.008838 | controller | changed 2025-12-01 00:33:45.021633 | 2025-12-01 00:33:45.021796 | TASK [Set selinux package] 2025-12-01 00:33:45.060468 | controller | ok 2025-12-01 00:33:45.071535 | 2025-12-01 00:33:45.071656 | TASK [Set selinux package (Fedora)] 2025-12-01 00:33:45.108005 | controller | ok 2025-12-01 00:33:45.114759 | 2025-12-01 00:33:45.114841 | TASK [Install selinux into virtualenv] 2025-12-01 00:33:47.704594 | controller | Collecting selinux-please-lie-to-me 2025-12-01 00:33:47.761268 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-01 00:33:48.211016 | controller | Collecting setuptools<50.0.0 2025-12-01 00:33:48.218107 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-01 00:33:48.260585 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 21.1 MB/s eta 0:00:00 2025-12-01 00:33:48.375427 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-01 00:33:48.375652 | controller | Attempting uninstall: setuptools 2025-12-01 00:33:48.379378 | controller | Found existing installation: setuptools 62.6.0 2025-12-01 00:33:48.467876 | controller | Uninstalling setuptools-62.6.0: 2025-12-01 00:33:48.480485 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-01 00:33:49.086174 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-01 00:33:49.258883 | controller | 2025-12-01 00:33:49.512229 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-01 00:33:49.512300 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-01 00:33:49.984572 | controller | ok: Runtime: 0:00:03.648002 2025-12-01 00:33:49.990151 | 2025-12-01 00:33:49.990210 | TASK [Install pytest-forked into virtualenv] 2025-12-01 00:33:51.327959 | controller | Collecting pytest-forked 2025-12-01 00:33:51.381795 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-01 00:33:51.434207 | controller | Collecting py 2025-12-01 00:33:51.439639 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-01 00:33:51.465588 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.2 MB/s eta 0:00:00 2025-12-01 00:33:51.609458 | controller | Collecting pytest>=3.10 2025-12-01 00:33:51.614072 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-12-01 00:33:51.632350 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 25.3 MB/s eta 0:00:00 2025-12-01 00:33:51.683969 | controller | Collecting iniconfig>=1.0.1 2025-12-01 00:33:51.688606 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-01 00:33:51.740297 | controller | Collecting packaging>=22 2025-12-01 00:33:51.744931 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-01 00:33:51.754032 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.4 MB/s eta 0:00:00 2025-12-01 00:33:51.791176 | controller | Collecting pluggy<2,>=1.5 2025-12-01 00:33:51.795153 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-01 00:33:51.856793 | controller | Collecting pygments>=2.7.2 2025-12-01 00:33:51.860990 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-01 00:33:51.884092 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 62.4 MB/s eta 0:00:00 2025-12-01 00:33:51.981302 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-01 00:33:54.021069 | 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.1 pytest-forked-1.6.0 2025-12-01 00:33:54.040550 | controller | 2025-12-01 00:33:54.328326 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-01 00:33:54.328400 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-01 00:33:54.879286 | controller | ok: Runtime: 0:00:03.605412 2025-12-01 00:33:54.891756 | 2025-12-01 00:33:54.891886 | TASK [Update pip] 2025-12-01 00:33:56.181038 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-01 00:33:56.413661 | controller | Collecting pip 2025-12-01 00:33:56.486950 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-01 00:33:56.565490 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.4 MB/s eta 0:00:00 2025-12-01 00:33:56.713638 | controller | Installing collected packages: pip 2025-12-01 00:33:56.714004 | controller | Attempting uninstall: pip 2025-12-01 00:33:56.717307 | controller | Found existing installation: pip 22.2.2 2025-12-01 00:33:56.923163 | controller | Uninstalling pip-22.2.2: 2025-12-01 00:33:56.946325 | controller | Successfully uninstalled pip-22.2.2 2025-12-01 00:33:58.540305 | controller | Successfully installed pip-25.3 2025-12-01 00:33:59.270429 | controller | ok: Runtime: 0:00:03.208744 2025-12-01 00:33:59.282298 | 2025-12-01 00:33:59.282424 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-01 00:34:00.154549 | controller | changed 2025-12-01 00:34:00.161574 | 2025-12-01 00:34:00.161657 | TASK [Install ansible into virtualenv] 2025-12-01 00:34:01.466940 | controller | Processing ./src/github.com/ansible/ansible 2025-12-01 00:34:01.472693 | controller | Installing build dependencies: started 2025-12-01 00:34:03.394996 | controller | Installing build dependencies: finished with status 'done' 2025-12-01 00:34:04.918543 | controller | Getting requirements to build wheel: started 2025-12-01 00:34:04.918632 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-01 00:34:05.787830 | controller | Preparing metadata (pyproject.toml): started 2025-12-01 00:34:05.787907 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-01 00:34:05.790920 | 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-01 00:34:05.794999 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-01 00:34:06.544331 | controller | ERROR 2025-12-01 00:34:06.544627 | controller | { 2025-12-01 00:34:06.544723 | controller | "delta": "0:00:05.170676", 2025-12-01 00:34:06.544768 | controller | "end": "2025-12-01 00:34:06.028914", 2025-12-01 00:34:06.544805 | controller | "msg": "non-zero return code", 2025-12-01 00:34:06.544859 | controller | "rc": 1, 2025-12-01 00:34:06.544895 | controller | "start": "2025-12-01 00:34:00.858238" 2025-12-01 00:34:06.544927 | controller | } failure 2025-12-01 00:34:06.547573 | 2025-12-01 00:34:06.547710 | PLAY RECAP 2025-12-01 00:34:06.547811 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-01 00:34:06.547866 | 2025-12-01 00:34:06.668463 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-01 00:34:06.669382 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-01 00:34:07.200619 | 2025-12-01 00:34:07.200752 | PLAY [all] 2025-12-01 00:34:07.222677 | 2025-12-01 00:34:07.222773 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-01 00:34:09.080076 | controller | changed: non-zero return code 2025-12-01 00:34:09.098852 | 2025-12-01 00:34:09.099037 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-01 00:34:09.119008 | controller | skipping: Conditional result was False 2025-12-01 00:34:09.138406 | 2025-12-01 00:34:09.138585 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-01 00:34:09.183072 | 2025-12-01 00:34:09.183538 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-01 00:34:09.212406 | 2025-12-01 00:34:09.212900 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-01 00:34:09.237967 | controller | skipping: Conditional result was False 2025-12-01 00:34:09.244037 | 2025-12-01 00:34:09.244103 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-01 00:34:09.275764 | 2025-12-01 00:34:09.275963 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-01 00:34:09.301845 | controller | skipping: Conditional result was False 2025-12-01 00:34:09.308205 | 2025-12-01 00:34:09.308274 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-01 00:34:09.333174 | controller | skipping: Conditional result was False 2025-12-01 00:34:09.339987 | 2025-12-01 00:34:09.340055 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-01 00:34:09.354001 | controller | skipping: Conditional result was False 2025-12-01 00:34:09.379572 | 2025-12-01 00:34:09.379623 | PLAY RECAP 2025-12-01 00:34:09.379679 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-01 00:34:09.379703 | 2025-12-01 00:34:09.468001 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-01 00:34:09.468837 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-01 00:34:10.045326 | 2025-12-01 00:34:10.045432 | PLAY [all:!appliance*] 2025-12-01 00:34:10.066411 | 2025-12-01 00:34:10.066486 | TASK [unregister the node] 2025-12-01 00:34:10.419730 | controller | skipping: Conditional result was False 2025-12-01 00:34:10.432320 | 2025-12-01 00:34:10.432545 | TASK [include_role : fetch-output] 2025-12-01 00:34:10.481442 | controller | ok 2025-12-01 00:34:10.519719 | 2025-12-01 00:34:10.519810 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-01 00:34:10.585450 | controller | skipping: Conditional result was False 2025-12-01 00:34:10.598988 | 2025-12-01 00:34:10.599130 | TASK [fetch-output : Set log path for single node] 2025-12-01 00:34:10.647637 | controller | ok 2025-12-01 00:34:10.659284 | 2025-12-01 00:34:10.659417 | LOOP [fetch-output : Ensure local output dirs] 2025-12-01 00:34:11.084692 | controller -> localhost | ok: "/var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/logs" 2025-12-01 00:34:11.318509 | controller -> localhost | changed: "/var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/artifacts" 2025-12-01 00:34:11.569371 | controller -> localhost | changed: "/var/lib/zuul/builds/8e6df85f9e9c468bb3a9f296002d3eee/work/docs" 2025-12-01 00:34:11.590409 | 2025-12-01 00:34:11.590583 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-01 00:34:13.857368 | controller | changed: 2025-12-01 00:34:13.857575 | controller | .d..t...... ./ 2025-12-01 00:34:13.857615 | controller | cd+++++++++ controller/ 2025-12-01 00:34:13.857677 | controller | changed: All items complete 2025-12-01 00:34:13.857734 | 2025-12-01 00:34:15.924487 | controller | changed: .d..t...... ./ 2025-12-01 00:34:17.974640 | controller | changed: .d..t...... ./ 2025-12-01 00:34:18.002215 | 2025-12-01 00:34:18.002358 | TASK [include_role : fetch-output-openshift] 2025-12-01 00:34:18.027768 | controller | skipping: Conditional result was False 2025-12-01 00:34:18.036887 | 2025-12-01 00:34:18.036989 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-01 00:34:18.080914 | controller | skipping: Conditional result was False 2025-12-01 00:34:18.090954 | controller | skipping: Conditional result was False 2025-12-01 00:34:18.131049 | 2025-12-01 00:34:18.131210 | PLAY [localhost] 2025-12-01 00:34:18.149632 | 2025-12-01 00:34:18.149759 | TASK [Run Zuul manifest role] 2025-12-01 00:34:18.170991 | localhost | ok 2025-12-01 00:34:18.189740 | 2025-12-01 00:34:18.189849 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-01 00:34:18.598255 | localhost | changed 2025-12-01 00:34:18.608427 | 2025-12-01 00:34:18.608559 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-01 00:34:18.654848 | localhost | ok 2025-12-01 00:34:18.672279 | 2025-12-01 00:34:18.672438 | TASK [Set zuul-log-path fact] 2025-12-01 00:34:18.700925 | localhost | ok 2025-12-01 00:34:18.755732 | 2025-12-01 00:34:18.755870 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-01 00:34:18.799201 | localhost | ok 2025-12-01 00:34:18.816215 | 2025-12-01 00:34:18.816339 | LOOP [Run upload-logs-swift role] 2025-12-01 00:34:18.865098 | localhost | Output suppressed because no_log was given 2025-12-01 00:34:18.911358 | 2025-12-01 00:34:18.911441 | TASK [Set zuul-log-path fact] 2025-12-01 00:34:18.946539 | localhost | skipping: Conditional result was False 2025-12-01 00:34:18.953041 | 2025-12-01 00:34:18.953104 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-01 00:34:19.395269 | localhost -> localhost | ok: Runtime: 0:00:00.008665 2025-12-01 00:34:19.406769 | 2025-12-01 00:34:19.406905 | TASK [upload-logs-swift : Upload logs to swift]