2025-11-24 00:07:02.114123 | Job console starting... 2025-11-24 00:07:02.136084 | Updating repositories 2025-11-24 00:07:02.387367 | Preparing job workspace 2025-11-24 00:07:08.226868 | Running Ansible setup... 2025-11-24 00:07:15.637858 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:07:16.328533 | 2025-11-24 00:07:16.328665 | PLAY [localhost] 2025-11-24 00:07:16.337362 | 2025-11-24 00:07:16.337441 | TASK [Gathering Facts] 2025-11-24 00:07:17.770238 | localhost | ok 2025-11-24 00:07:17.804168 | 2025-11-24 00:07:17.804359 | TASK [Setup log path fact] 2025-11-24 00:07:17.827915 | localhost | ok 2025-11-24 00:07:17.845197 | 2025-11-24 00:07:17.845295 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:07:17.876392 | localhost | ok 2025-11-24 00:07:17.887276 | 2025-11-24 00:07:17.887366 | TASK [emit-job-header : Print job information] 2025-11-24 00:07:17.937922 | # Job Information 2025-11-24 00:07:17.938086 | Ansible Version: 2.15.12 2025-11-24 00:07:17.938127 | Job: ansible-test-sanity-docker-devel 2025-11-24 00:07:17.938155 | Pipeline: periodic 2025-11-24 00:07:17.938180 | Executor: ze04.softwarefactory-project.io 2025-11-24 00:07:17.938205 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-24 00:07:17.938233 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/dbe/ansible/dbed627980d04661875e44e7f0c52110/ 2025-11-24 00:07:17.938258 | Event ID: db80f5515f954e34b34bdcccc30c1493 2025-11-24 00:07:17.943482 | 2025-11-24 00:07:17.943565 | LOOP [emit-job-header : Print node information] 2025-11-24 00:07:18.073051 | localhost | ok: 2025-11-24 00:07:18.073266 | localhost | # Node Information 2025-11-24 00:07:18.073303 | localhost | Inventory Hostname: controller 2025-11-24 00:07:18.073331 | localhost | Hostname: np0005532863 2025-11-24 00:07:18.073358 | localhost | Username: zuul 2025-11-24 00:07:18.073390 | localhost | Distro: Fedora 37 2025-11-24 00:07:18.073415 | localhost | Provider: ansible-vexxhost-ams1 2025-11-24 00:07:18.073440 | localhost | Region: ams1 2025-11-24 00:07:18.073464 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-24 00:07:18.073488 | localhost | Product Name: OpenStack Nova 2025-11-24 00:07:18.073520 | localhost | Interface IP: 38.129.16.196 2025-11-24 00:07:18.102770 | 2025-11-24 00:07:18.103090 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-24 00:07:18.586783 | localhost -> localhost | changed 2025-11-24 00:07:18.599970 | 2025-11-24 00:07:18.600115 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-24 00:07:19.685468 | localhost -> localhost | changed 2025-11-24 00:07:19.735402 | 2025-11-24 00:07:19.735508 | PLAY [all:!appliance*] 2025-11-24 00:07:19.759757 | 2025-11-24 00:07:19.759877 | TASK [include_role : start-zuul-console] 2025-11-24 00:07:19.783667 | controller | ok 2025-11-24 00:07:19.803546 | 2025-11-24 00:07:19.803653 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-24 00:07:20.750532 | controller | ok 2025-11-24 00:07:20.779556 | 2025-11-24 00:07:20.779828 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-24 00:07:22.653989 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-24 00:07:22.668808 | 2025-11-24 00:07:22.668938 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-24 00:07:23.040591 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.054922 | 2025-11-24 00:07:23.055162 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-24 00:07:23.093082 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.106448 | 2025-11-24 00:07:23.106607 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-24 00:07:23.133365 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.147332 | 2025-11-24 00:07:23.147470 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-24 00:07:23.174196 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.188342 | 2025-11-24 00:07:23.188484 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-24 00:07:23.215397 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.229559 | 2025-11-24 00:07:23.229761 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-24 00:07:23.256527 | controller | skipping: Conditional result was False 2025-11-24 00:07:23.280819 | 2025-11-24 00:07:23.280985 | TASK [Disable Fedora Modular] 2025-11-24 00:07:24.130057 | controller | changed 2025-11-24 00:07:24.136764 | 2025-11-24 00:07:24.136904 | TASK [Enable EPEL] 2025-11-24 00:07:24.161001 | controller | skipping: Conditional result was False 2025-11-24 00:07:24.168223 | 2025-11-24 00:07:24.168333 | TASK [Register the RHEL node] 2025-11-24 00:07:24.569911 | 2025-11-24 00:07:24.570190 | TASK [Show the subscription-manager status] 2025-11-24 00:07:24.956487 | controller | skipping: Conditional result was False 2025-11-24 00:07:24.971265 | 2025-11-24 00:07:24.971407 | TASK [Enable EPEL on RHEL] 2025-11-24 00:07:25.351312 | controller | skipping: Conditional result was False 2025-11-24 00:07:25.364589 | 2025-11-24 00:07:25.364765 | TASK [Install git and tox] 2025-11-24 00:09:51.655378 | controller | changed 2025-11-24 00:09:51.670665 | 2025-11-24 00:09:51.670873 | TASK [include_role : prepare-workspace] 2025-11-24 00:09:51.713269 | controller | ok 2025-11-24 00:09:51.752080 | 2025-11-24 00:09:51.752226 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-24 00:09:52.549293 | controller | ok 2025-11-24 00:09:52.567170 | 2025-11-24 00:09:52.567382 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-24 00:10:07.896919 | controller | Output suppressed because no_log was given 2025-11-24 00:10:07.910946 | 2025-11-24 00:10:07.911062 | TASK [include_role : prepare-workspace-openshift] 2025-11-24 00:10:07.927316 | controller | skipping: Conditional result was False 2025-11-24 00:10:07.950783 | 2025-11-24 00:10:07.950862 | PLAY [all:!appliance] 2025-11-24 00:10:07.967880 | 2025-11-24 00:10:07.967987 | TASK [Run add-build-sshkey role (RSA)] 2025-11-24 00:10:07.987894 | controller | ok 2025-11-24 00:10:08.003501 | 2025-11-24 00:10:08.003613 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:10:08.223000 | controller -> localhost | ok 2025-11-24 00:10:08.231921 | 2025-11-24 00:10:08.232055 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:10:08.255313 | controller | ok 2025-11-24 00:10:08.275583 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:10:08.282568 | 2025-11-24 00:10:08.282664 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:10:08.859256 | controller -> localhost | Generating public/private rsa key pair. 2025-11-24 00:10:08.859773 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_rsa. 2025-11-24 00:10:08.859862 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_rsa.pub. 2025-11-24 00:10:08.859919 | controller -> localhost | The key fingerprint is: 2025-11-24 00:10:08.860001 | controller -> localhost | SHA256:NDmyZJ/pskf5PSGBXQnSaSf/KOF26c4WJwB33EzJ9yg zuul-build-sshkey 2025-11-24 00:10:08.860050 | controller -> localhost | The key's randomart image is: 2025-11-24 00:10:08.860095 | controller -> localhost | +---[RSA 2048]----+ 2025-11-24 00:10:08.860139 | controller -> localhost | | ...+ *.. | 2025-11-24 00:10:08.860187 | controller -> localhost | | .o* * = .| 2025-11-24 00:10:08.860231 | controller -> localhost | | + =* * o.| 2025-11-24 00:10:08.860277 | controller -> localhost | | o =.== E . .| 2025-11-24 00:10:08.860321 | controller -> localhost | | . So + = | 2025-11-24 00:10:08.860381 | controller -> localhost | | .o = B o | 2025-11-24 00:10:08.860440 | controller -> localhost | | ...o * = | 2025-11-24 00:10:08.860491 | controller -> localhost | | o. ..= | 2025-11-24 00:10:08.860536 | controller -> localhost | | .. oo. | 2025-11-24 00:10:08.860586 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:10:08.860750 | controller -> localhost | ok: Runtime: 0:00:00.202099 2025-11-24 00:10:08.886722 | 2025-11-24 00:10:08.886974 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:10:08.927474 | controller | ok 2025-11-24 00:10:08.943850 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:10:08.962022 | 2025-11-24 00:10:08.962197 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:10:08.988941 | controller | skipping: Conditional result was False 2025-11-24 00:10:08.995547 | 2025-11-24 00:10:08.995643 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:10:10.030598 | controller | changed 2025-11-24 00:10:10.046458 | 2025-11-24 00:10:10.046651 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:10:10.667698 | controller | ok 2025-11-24 00:10:10.677193 | 2025-11-24 00:10:10.677297 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:10:13.607196 | controller | changed 2025-11-24 00:10:13.617942 | 2025-11-24 00:10:13.618056 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:10:16.531483 | controller | changed 2025-11-24 00:10:16.542635 | 2025-11-24 00:10:16.542791 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:10:16.579121 | controller | skipping: Conditional result was False 2025-11-24 00:10:16.587035 | 2025-11-24 00:10:16.587133 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:10:17.000672 | controller -> localhost | changed 2025-11-24 00:10:17.025083 | 2025-11-24 00:10:17.025253 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:10:17.348663 | controller -> localhost | Identity added: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_rsa (zuul-build-sshkey) 2025-11-24 00:10:17.349037 | controller -> localhost | ok: Runtime: 0:00:00.013521 2025-11-24 00:10:17.359452 | 2025-11-24 00:10:17.359570 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:10:18.307519 | controller | ok 2025-11-24 00:10:18.318984 | 2025-11-24 00:10:18.319087 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:10:18.366230 | controller | skipping: Conditional result was False 2025-11-24 00:10:18.399847 | 2025-11-24 00:10:18.400091 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-24 00:10:18.441247 | controller | ok 2025-11-24 00:10:18.474097 | 2025-11-24 00:10:18.474615 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:10:18.747234 | controller -> localhost | ok 2025-11-24 00:10:18.754802 | 2025-11-24 00:10:18.754882 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:10:18.788174 | controller | ok 2025-11-24 00:10:18.804943 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:10:18.814393 | 2025-11-24 00:10:18.814521 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:10:19.097572 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-24 00:10:19.097863 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_ecdsa. 2025-11-24 00:10:19.097917 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_ecdsa.pub. 2025-11-24 00:10:19.097969 | controller -> localhost | The key fingerprint is: 2025-11-24 00:10:19.098008 | controller -> localhost | SHA256:KCSQ1lGv+5zxRdCaiVc/jAwtSa89N7cNsIraE8zbm0Y zuul-build-sshkey 2025-11-24 00:10:19.098045 | controller -> localhost | The key's randomart image is: 2025-11-24 00:10:19.098122 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-24 00:10:19.098165 | controller -> localhost | |....o. . | 2025-11-24 00:10:19.098200 | controller -> localhost | |.o . . . = | 2025-11-24 00:10:19.098233 | controller -> localhost | |. . . . = =. | 2025-11-24 00:10:19.098270 | controller -> localhost | | o ... % +o | 2025-11-24 00:10:19.098302 | controller -> localhost | | ...+S* *.*.. | 2025-11-24 00:10:19.098336 | controller -> localhost | | .. =.E.o +.o| 2025-11-24 00:10:19.098370 | controller -> localhost | | . ..=.. ..| 2025-11-24 00:10:19.098402 | controller -> localhost | | oo* +. | 2025-11-24 00:10:19.098437 | controller -> localhost | | .+.+o. | 2025-11-24 00:10:19.098470 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:10:19.098555 | controller -> localhost | ok: Runtime: 0:00:00.008051 2025-11-24 00:10:19.110208 | 2025-11-24 00:10:19.110334 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:10:19.135859 | controller | ok 2025-11-24 00:10:19.147449 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:10:19.161631 | 2025-11-24 00:10:19.161757 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:10:19.198629 | controller | skipping: Conditional result was False 2025-11-24 00:10:19.215066 | 2025-11-24 00:10:19.215186 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:10:20.095863 | controller | changed 2025-11-24 00:10:20.110671 | 2025-11-24 00:10:20.110859 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:10:20.734021 | controller | ok 2025-11-24 00:10:20.747297 | 2025-11-24 00:10:20.747434 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:10:23.692566 | controller | changed 2025-11-24 00:10:23.710600 | 2025-11-24 00:10:23.710838 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:10:26.608128 | controller | changed 2025-11-24 00:10:26.619265 | 2025-11-24 00:10:26.619410 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:10:26.655345 | controller | skipping: Conditional result was False 2025-11-24 00:10:26.665081 | 2025-11-24 00:10:26.665201 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:10:26.956015 | controller -> localhost | changed 2025-11-24 00:10:26.974656 | 2025-11-24 00:10:26.974841 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:10:27.327806 | controller -> localhost | Identity added: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/dbed627980d04661875e44e7f0c52110_id_ecdsa (zuul-build-sshkey) 2025-11-24 00:10:27.328141 | controller -> localhost | ok: Runtime: 0:00:00.008931 2025-11-24 00:10:27.342910 | 2025-11-24 00:10:27.343187 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:10:28.018166 | controller | ok 2025-11-24 00:10:28.025779 | 2025-11-24 00:10:28.025878 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:10:28.061311 | controller | skipping: Conditional result was False 2025-11-24 00:10:28.073858 | 2025-11-24 00:10:28.073936 | TASK [include_role : remove-zuul-sshkey] 2025-11-24 00:10:28.099000 | controller | skipping: Conditional result was False 2025-11-24 00:10:28.108292 | 2025-11-24 00:10:28.108372 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-24 00:10:28.719922 | controller | ok: "logs" 2025-11-24 00:10:28.720403 | controller | ok: All items complete 2025-11-24 00:10:28.720500 | 2025-11-24 00:10:29.296818 | controller | ok: "artifacts" 2025-11-24 00:10:29.876280 | controller | ok: "docs" 2025-11-24 00:10:29.892813 | 2025-11-24 00:10:29.893025 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-24 00:10:30.518531 | controller | changed: "logs" 2025-11-24 00:10:31.108015 | controller | changed: "artifacts" 2025-11-24 00:10:31.691576 | controller | changed: "docs" 2025-11-24 00:10:31.741456 | 2025-11-24 00:10:31.741634 | PLAY RECAP 2025-11-24 00:10:31.741895 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-24 00:10:31.741991 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-24 00:10:31.742055 | 2025-11-24 00:10:31.854925 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:10:31.855869 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:10:32.501459 | 2025-11-24 00:10:32.501619 | PLAY [all] 2025-11-24 00:10:32.527805 | 2025-11-24 00:10:32.527914 | TASK [Install binary dependencies] 2025-11-24 00:10:32.576570 | controller | ok 2025-11-24 00:10:32.597984 | 2025-11-24 00:10:32.598105 | TASK [bindep : Include find tasks] 2025-11-24 00:10:32.639526 | controller | ok 2025-11-24 00:10:32.652308 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-24 00:10:32.658459 | 2025-11-24 00:10:32.658524 | TASK [bindep : Look for bindep.txt] 2025-11-24 00:10:33.553077 | controller | ok 2025-11-24 00:10:33.564268 | 2025-11-24 00:10:33.564434 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:10:33.580541 | controller | skipping: Conditional result was False 2025-11-24 00:10:33.592827 | 2025-11-24 00:10:33.593003 | TASK [bindep : Look for other-requirements.txt] 2025-11-24 00:10:34.187024 | controller | ok 2025-11-24 00:10:34.193132 | 2025-11-24 00:10:34.193210 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:10:34.227587 | controller | skipping: Conditional result was False 2025-11-24 00:10:34.234168 | 2025-11-24 00:10:34.234247 | TASK [bindep : Look for bindep fallback file] 2025-11-24 00:10:34.279768 | controller | skipping: Conditional result was False 2025-11-24 00:10:34.296483 | 2025-11-24 00:10:34.296812 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:10:34.336286 | controller | skipping: Conditional result was False 2025-11-24 00:10:34.350832 | 2025-11-24 00:10:34.351164 | TASK [bindep : Include bindep tasks] 2025-11-24 00:10:34.379849 | controller | skipping: Conditional result was False 2025-11-24 00:10:34.394087 | 2025-11-24 00:10:34.394274 | TASK [bindep : Include install tasks] 2025-11-24 00:10:34.430574 | controller | skipping: Conditional result was False 2025-11-24 00:10:34.440346 | 2025-11-24 00:10:34.440642 | LOOP [bindep : Include package tasks] 2025-11-24 00:10:34.526052 | 2025-11-24 00:10:34.526261 | TASK [Run test-setup role] 2025-11-24 00:10:34.548531 | controller | ok 2025-11-24 00:10:34.574176 | 2025-11-24 00:10:34.574284 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-24 00:10:35.165155 | controller | ok 2025-11-24 00:10:35.180363 | 2025-11-24 00:10:35.180505 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-24 00:10:35.549937 | controller | skipping: Conditional result was False 2025-11-24 00:10:35.607668 | 2025-11-24 00:10:35.607883 | PLAY RECAP 2025-11-24 00:10:35.608072 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:10:35.608119 | 2025-11-24 00:10:35.721669 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:10:35.723563 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:10:36.356131 | 2025-11-24 00:10:36.356257 | PLAY [controller] 2025-11-24 00:10:36.378645 | 2025-11-24 00:10:36.378777 | TASK [Create the /root directory] 2025-11-24 00:10:37.379919 | controller | ok 2025-11-24 00:10:37.396629 | 2025-11-24 00:10:37.396876 | TASK [Install glibc-langpack-en] 2025-11-24 00:10:44.371119 | controller | ok: Nothing to do 2025-11-24 00:10:44.384109 | 2025-11-24 00:10:44.384274 | TASK [Ensure controller directory exists] 2025-11-24 00:10:45.180771 | controller | changed 2025-11-24 00:10:45.193778 | 2025-11-24 00:10:45.193930 | TASK [Install container runtime] 2025-11-24 00:10:45.261761 | controller | ok 2025-11-24 00:10:45.313014 | 2025-11-24 00:10:45.313153 | LOOP [ensure-podman : Find distribution installation] 2025-11-24 00:10:45.344170 | controller | ok: "/var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-24 00:10:45.362211 | controller | included: /var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-24 00:10:45.371445 | 2025-11-24 00:10:45.371539 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-24 00:12:31.825907 | controller | changed 2025-11-24 00:12:31.834024 | 2025-11-24 00:12:31.834095 | TASK [ensure-podman : Fetch podman version] 2025-11-24 00:12:32.894807 | controller | Client: Podman Engine 2025-11-24 00:12:32.929344 | controller | Version: 4.6.2 2025-11-24 00:12:32.929498 | controller | API Version: 4.6.2 2025-11-24 00:12:32.929510 | controller | Go Version: go1.19.12 2025-11-24 00:12:32.929529 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:12:32.929537 | controller | OS/Arch: linux/amd64 2025-11-24 00:12:33.192481 | controller | ok: Runtime: 0:00:00.249323 2025-11-24 00:12:33.207276 | 2025-11-24 00:12:33.207479 | TASK [ensure-podman : Print podman version installed] 2025-11-24 00:12:33.258220 | Podman version: Client: Podman Engine 2025-11-24 00:12:33.258509 | Version: 4.6.2 2025-11-24 00:12:33.258591 | API Version: 4.6.2 2025-11-24 00:12:33.258638 | Go Version: go1.19.12 2025-11-24 00:12:33.258687 | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:12:33.258792 | OS/Arch: linux/amd64 2025-11-24 00:12:33.271770 | 2025-11-24 00:12:33.271936 | TASK [ensure-podman : Validate podman engine] 2025-11-24 00:12:33.644295 | controller | skipping: Conditional result was False 2025-11-24 00:12:33.654997 | 2025-11-24 00:12:33.655758 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-24 00:12:33.684851 | controller | skipping: Conditional result was False 2025-11-24 00:12:33.703034 | 2025-11-24 00:12:33.703180 | TASK [Ensure python3.8 is present] 2025-11-24 00:12:33.728533 | controller | skipping: Conditional result was False 2025-11-24 00:12:33.735979 | 2025-11-24 00:12:33.736063 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-24 00:12:33.758947 | controller | ok 2025-11-24 00:12:33.782930 | 2025-11-24 00:12:33.783054 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-24 00:12:36.849603 | controller | ok: Nothing to do 2025-11-24 00:12:36.860001 | 2025-11-24 00:12:36.860100 | TASK [our-ensure-python : Also install python3-devel] 2025-11-24 00:13:19.997835 | controller | changed 2025-11-24 00:13:20.048265 | 2025-11-24 00:13:20.048381 | TASK [Run ensure-virtualenv role] 2025-11-24 00:13:20.067628 | controller | ok 2025-11-24 00:13:20.095770 | 2025-11-24 00:13:20.095888 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-24 00:13:20.813017 | controller | /usr/bin/virtualenv 2025-11-24 00:13:20.952491 | controller | ok: Runtime: 0:00:00.004681 2025-11-24 00:13:20.959433 | 2025-11-24 00:13:20.959532 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-24 00:13:20.980214 | controller | skipping: Conditional result was False 2025-11-24 00:13:20.980643 | controller | ok: All items complete 2025-11-24 00:13:20.980745 | 2025-11-24 00:13:21.012111 | 2025-11-24 00:13:21.012282 | TASK [Find the full path of the Python interpreter] 2025-11-24 00:13:21.578304 | controller | /usr/bin/python3 2025-11-24 00:13:21.881500 | controller | ok 2025-11-24 00:13:21.889152 | 2025-11-24 00:13:21.889277 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-24 00:13:23.377424 | controller | created virtual environment CPython3.11.0.final.0-64 in 682ms 2025-11-24 00:13:23.432502 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-24 00:13:23.433454 | 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-11-24 00:13:23.433814 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-24 00:13:23.433841 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-24 00:13:23.756585 | controller | changed 2025-11-24 00:13:23.763182 | 2025-11-24 00:13:23.763260 | TASK [Set selinux package] 2025-11-24 00:13:23.785033 | controller | ok 2025-11-24 00:13:23.791771 | 2025-11-24 00:13:23.791885 | TASK [Set selinux package (Fedora)] 2025-11-24 00:13:23.836762 | controller | ok 2025-11-24 00:13:23.845042 | 2025-11-24 00:13:23.845181 | TASK [Install selinux into virtualenv] 2025-11-24 00:13:26.452430 | controller | Collecting selinux-please-lie-to-me 2025-11-24 00:13:26.506736 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-24 00:13:26.952022 | controller | Collecting setuptools<50.0.0 2025-11-24 00:13:26.959449 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-24 00:13:27.023177 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 13.9 MB/s eta 0:00:00 2025-11-24 00:13:27.132819 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-24 00:13:27.133139 | controller | Attempting uninstall: setuptools 2025-11-24 00:13:27.136662 | controller | Found existing installation: setuptools 62.6.0 2025-11-24 00:13:27.223646 | controller | Uninstalling setuptools-62.6.0: 2025-11-24 00:13:27.235379 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-24 00:13:27.836103 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-24 00:13:28.009522 | controller | 2025-11-24 00:13:28.237852 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:13:28.237904 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:13:28.728885 | controller | ok: Runtime: 0:00:03.618284 2025-11-24 00:13:28.741879 | 2025-11-24 00:13:28.742058 | TASK [Install pytest-forked into virtualenv] 2025-11-24 00:13:30.046931 | controller | Collecting pytest-forked 2025-11-24 00:13:30.099598 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-24 00:13:30.147385 | controller | Collecting py 2025-11-24 00:13:30.151594 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-24 00:13:30.179019 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.8 MB/s eta 0:00:00 2025-11-24 00:13:30.320197 | controller | Collecting pytest>=3.10 2025-11-24 00:13:30.325663 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-11-24 00:13:30.343410 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 29.0 MB/s eta 0:00:00 2025-11-24 00:13:30.388506 | controller | Collecting iniconfig>=1.0.1 2025-11-24 00:13:30.392288 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-24 00:13:30.442992 | controller | Collecting packaging>=22 2025-11-24 00:13:30.446922 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-24 00:13:30.454567 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.7 MB/s eta 0:00:00 2025-11-24 00:13:30.491229 | controller | Collecting pluggy<2,>=1.5 2025-11-24 00:13:30.495277 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-24 00:13:30.553042 | controller | Collecting pygments>=2.7.2 2025-11-24 00:13:30.557426 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-24 00:13:30.577567 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 72.4 MB/s eta 0:00:00 2025-11-24 00:13:30.672874 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-24 00:13:32.675312 | 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-11-24 00:13:32.694793 | controller | 2025-11-24 00:13:32.897120 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:13:32.897171 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:13:33.140437 | controller | ok: Runtime: 0:00:03.425165 2025-11-24 00:13:33.154171 | 2025-11-24 00:13:33.154342 | TASK [Update pip] 2025-11-24 00:13:34.397442 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-24 00:13:34.615694 | controller | Collecting pip 2025-11-24 00:13:34.682068 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-24 00:13:34.756353 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 26.0 MB/s eta 0:00:00 2025-11-24 00:13:34.870731 | controller | Installing collected packages: pip 2025-11-24 00:13:34.871054 | controller | Attempting uninstall: pip 2025-11-24 00:13:34.874360 | controller | Found existing installation: pip 22.2.2 2025-11-24 00:13:35.075667 | controller | Uninstalling pip-22.2.2: 2025-11-24 00:13:35.100877 | controller | Successfully uninstalled pip-22.2.2 2025-11-24 00:13:36.894990 | controller | Successfully installed pip-25.3 2025-11-24 00:13:37.540220 | controller | ok: Runtime: 0:00:03.149027 2025-11-24 00:13:37.549770 | 2025-11-24 00:13:37.549901 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-24 00:13:38.363583 | controller | changed 2025-11-24 00:13:38.377739 | 2025-11-24 00:13:38.377914 | TASK [Install ansible into virtualenv] 2025-11-24 00:13:39.535571 | controller | Processing ./src/github.com/ansible/ansible 2025-11-24 00:13:39.542585 | controller | Installing build dependencies: started 2025-11-24 00:13:41.520683 | controller | Installing build dependencies: finished with status 'done' 2025-11-24 00:13:41.521709 | controller | Getting requirements to build wheel: started 2025-11-24 00:13:42.984522 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-24 00:13:43.745265 | controller | Preparing metadata (pyproject.toml): started 2025-11-24 00:13:43.745313 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-24 00:13:43.746922 | 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-11-24 00:13:43.746948 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-24 00:13:44.274280 | controller | ERROR 2025-11-24 00:13:44.274483 | controller | { 2025-11-24 00:13:44.274512 | controller | "delta": "0:00:04.865008", 2025-11-24 00:13:44.274532 | controller | "end": "2025-11-24 00:13:43.886582", 2025-11-24 00:13:44.274550 | controller | "msg": "non-zero return code", 2025-11-24 00:13:44.274580 | controller | "rc": 1, 2025-11-24 00:13:44.274603 | controller | "start": "2025-11-24 00:13:39.021574" 2025-11-24 00:13:44.274619 | controller | } failure 2025-11-24 00:13:44.276304 | 2025-11-24 00:13:44.276367 | PLAY RECAP 2025-11-24 00:13:44.276422 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-24 00:13:44.276447 | 2025-11-24 00:13:44.387861 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:13:44.388865 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:13:44.956012 | 2025-11-24 00:13:44.956134 | PLAY [all] 2025-11-24 00:13:44.978763 | 2025-11-24 00:13:44.978864 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-24 00:13:46.786647 | controller | changed: non-zero return code 2025-11-24 00:13:46.792576 | 2025-11-24 00:13:46.792663 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-24 00:13:46.817580 | controller | skipping: Conditional result was False 2025-11-24 00:13:46.828105 | 2025-11-24 00:13:46.828264 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-24 00:13:46.856593 | 2025-11-24 00:13:46.856842 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-24 00:13:46.888061 | 2025-11-24 00:13:46.888225 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-24 00:13:46.902055 | controller | skipping: Conditional result was False 2025-11-24 00:13:46.909546 | 2025-11-24 00:13:46.909630 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-24 00:13:46.940839 | 2025-11-24 00:13:46.941020 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-24 00:13:46.960335 | controller | skipping: Conditional result was False 2025-11-24 00:13:46.972852 | 2025-11-24 00:13:46.973056 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-24 00:13:46.998830 | controller | skipping: Conditional result was False 2025-11-24 00:13:47.006837 | 2025-11-24 00:13:47.007012 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-24 00:13:47.022152 | controller | skipping: Conditional result was False 2025-11-24 00:13:47.059132 | 2025-11-24 00:13:47.059339 | PLAY RECAP 2025-11-24 00:13:47.059481 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:13:47.059506 | 2025-11-24 00:13:47.172247 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:13:47.174216 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-24 00:13:47.763979 | 2025-11-24 00:13:47.764107 | PLAY [all:!appliance*] 2025-11-24 00:13:47.787639 | 2025-11-24 00:13:47.787809 | TASK [unregister the node] 2025-11-24 00:13:48.141383 | controller | skipping: Conditional result was False 2025-11-24 00:13:48.149864 | 2025-11-24 00:13:48.150054 | TASK [include_role : fetch-output] 2025-11-24 00:13:48.194272 | controller | ok 2025-11-24 00:13:48.222523 | 2025-11-24 00:13:48.222642 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-24 00:13:48.268667 | controller | skipping: Conditional result was False 2025-11-24 00:13:48.278827 | 2025-11-24 00:13:48.278943 | TASK [fetch-output : Set log path for single node] 2025-11-24 00:13:48.329540 | controller | ok 2025-11-24 00:13:48.341651 | 2025-11-24 00:13:48.341789 | LOOP [fetch-output : Ensure local output dirs] 2025-11-24 00:13:48.759613 | controller -> localhost | ok: "/var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/logs" 2025-11-24 00:13:49.001726 | controller -> localhost | changed: "/var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/artifacts" 2025-11-24 00:13:49.222426 | controller -> localhost | changed: "/var/lib/zuul/builds/dbed627980d04661875e44e7f0c52110/work/docs" 2025-11-24 00:13:49.234890 | 2025-11-24 00:13:49.234991 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-24 00:13:51.471268 | controller | changed: 2025-11-24 00:13:51.471479 | controller | .d..t...... ./ 2025-11-24 00:13:51.471515 | controller | cd+++++++++ controller/ 2025-11-24 00:13:51.471555 | controller | changed: All items complete 2025-11-24 00:13:51.471580 | 2025-11-24 00:13:53.503864 | controller | changed: .d..t...... ./ 2025-11-24 00:13:55.608026 | controller | changed: .d..t...... ./ 2025-11-24 00:13:55.629580 | 2025-11-24 00:13:55.629818 | TASK [include_role : fetch-output-openshift] 2025-11-24 00:13:55.655482 | controller | skipping: Conditional result was False 2025-11-24 00:13:55.667081 | 2025-11-24 00:13:55.667240 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-24 00:13:55.698354 | controller | skipping: Conditional result was False 2025-11-24 00:13:55.707880 | controller | skipping: Conditional result was False 2025-11-24 00:13:55.749320 | 2025-11-24 00:13:55.749459 | PLAY [localhost] 2025-11-24 00:13:55.767721 | 2025-11-24 00:13:55.767829 | TASK [Run Zuul manifest role] 2025-11-24 00:13:55.787273 | localhost | ok 2025-11-24 00:13:55.808786 | 2025-11-24 00:13:55.808877 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-24 00:13:56.238735 | localhost | changed 2025-11-24 00:13:56.247267 | 2025-11-24 00:13:56.247365 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-24 00:13:56.283241 | localhost | ok 2025-11-24 00:13:56.294246 | 2025-11-24 00:13:56.294346 | TASK [Set zuul-log-path fact] 2025-11-24 00:13:56.316376 | localhost | ok 2025-11-24 00:13:56.370589 | 2025-11-24 00:13:56.370745 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:13:56.401778 | localhost | ok 2025-11-24 00:13:56.412617 | 2025-11-24 00:13:56.412745 | LOOP [Run upload-logs-swift role] 2025-11-24 00:13:56.450660 | localhost | Output suppressed because no_log was given 2025-11-24 00:13:56.487031 | 2025-11-24 00:13:56.487147 | TASK [Set zuul-log-path fact] 2025-11-24 00:13:56.522572 | localhost | skipping: Conditional result was False 2025-11-24 00:13:56.532964 | 2025-11-24 00:13:56.533086 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-24 00:13:56.934104 | localhost -> localhost | ok: Runtime: 0:00:00.009173 2025-11-24 00:13:56.943475 | 2025-11-24 00:13:56.943574 | TASK [upload-logs-swift : Upload logs to swift]