2025-10-07 00:11:56.606062 | Job console starting... 2025-10-07 00:11:56.616391 | Updating repositories 2025-10-07 00:11:56.742073 | Preparing job workspace 2025-10-07 00:12:00.333100 | Running Ansible setup... 2025-10-07 00:12:07.096547 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-07 00:12:07.683246 | 2025-10-07 00:12:07.683369 | PLAY [localhost] 2025-10-07 00:12:07.692001 | 2025-10-07 00:12:07.692084 | TASK [Gathering Facts] 2025-10-07 00:12:08.712098 | localhost | ok 2025-10-07 00:12:08.749256 | 2025-10-07 00:12:08.749486 | TASK [Setup log path fact] 2025-10-07 00:12:08.770300 | localhost | ok 2025-10-07 00:12:08.786926 | 2025-10-07 00:12:08.787024 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-07 00:12:08.838049 | localhost | ok 2025-10-07 00:12:08.849299 | 2025-10-07 00:12:08.849414 | TASK [emit-job-header : Print job information] 2025-10-07 00:12:08.901716 | # Job Information 2025-10-07 00:12:08.902198 | Ansible Version: 2.15.12 2025-10-07 00:12:08.902252 | Job: ansible-test-sanity-docker-devel 2025-10-07 00:12:08.902283 | Pipeline: periodic 2025-10-07 00:12:08.902310 | Executor: ze02.softwarefactory-project.io 2025-10-07 00:12:08.902336 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-07 00:12:08.902366 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/327/ansible/327130e19b7f4232b82b20f5642ca167/ 2025-10-07 00:12:08.902393 | Event ID: f91e81a870a84043a9d92fb3c45463b5 2025-10-07 00:12:08.908050 | 2025-10-07 00:12:08.908156 | LOOP [emit-job-header : Print node information] 2025-10-07 00:12:09.024788 | localhost | ok: 2025-10-07 00:12:09.025006 | localhost | # Node Information 2025-10-07 00:12:09.025035 | localhost | Inventory Hostname: controller 2025-10-07 00:12:09.025055 | localhost | Hostname: ip-172-16-151-85 2025-10-07 00:12:09.025073 | localhost | Username: zuul-worker 2025-10-07 00:12:09.025093 | localhost | Distro: Fedora 37 2025-10-07 00:12:09.025111 | localhost | Provider: ansible-us-east-2 2025-10-07 00:12:09.025129 | localhost | Region: us-east-2 2025-10-07 00:12:09.025146 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-07 00:12:09.025186 | localhost | Product Name: t3.small 2025-10-07 00:12:09.025203 | localhost | Interface IP: 3.128.18.226 2025-10-07 00:12:09.052714 | 2025-10-07 00:12:09.052860 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-07 00:12:09.513992 | localhost -> localhost | changed 2025-10-07 00:12:09.522052 | 2025-10-07 00:12:09.522151 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-07 00:12:10.475751 | localhost -> localhost | changed 2025-10-07 00:12:10.496291 | 2025-10-07 00:12:10.496362 | PLAY [all:!appliance*] 2025-10-07 00:12:10.512611 | 2025-10-07 00:12:10.512707 | TASK [include_role : start-zuul-console] 2025-10-07 00:12:10.531925 | controller | ok 2025-10-07 00:12:10.560733 | 2025-10-07 00:12:10.560869 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-07 00:12:11.245770 | controller | ok 2025-10-07 00:12:11.268201 | 2025-10-07 00:12:11.268392 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-07 00:12:13.001062 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-07 00:12:13.012467 | 2025-10-07 00:12:13.012619 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-07 00:12:13.148840 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.156497 | 2025-10-07 00:12:13.156648 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-07 00:12:13.184300 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.191224 | 2025-10-07 00:12:13.191353 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-07 00:12:13.215160 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.221660 | 2025-10-07 00:12:13.221793 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-07 00:12:13.236747 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.244214 | 2025-10-07 00:12:13.244524 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-07 00:12:13.272437 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.278615 | 2025-10-07 00:12:13.278737 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-07 00:12:13.303437 | controller | skipping: Conditional result was False 2025-10-07 00:12:13.315778 | 2025-10-07 00:12:13.315899 | TASK [Disable Fedora Modular] 2025-10-07 00:12:14.096014 | controller | changed 2025-10-07 00:12:14.107075 | 2025-10-07 00:12:14.107209 | TASK [Enable EPEL] 2025-10-07 00:12:14.132547 | controller | skipping: Conditional result was False 2025-10-07 00:12:14.142393 | 2025-10-07 00:12:14.142514 | TASK [Register the RHEL node] 2025-10-07 00:12:14.294273 | 2025-10-07 00:12:14.294548 | TASK [Show the subscription-manager status] 2025-10-07 00:12:14.488259 | controller | skipping: Conditional result was False 2025-10-07 00:12:14.496210 | 2025-10-07 00:12:14.496330 | TASK [Enable EPEL on RHEL] 2025-10-07 00:12:14.632381 | controller | skipping: Conditional result was False 2025-10-07 00:12:14.638361 | 2025-10-07 00:12:14.638429 | TASK [Install git and tox] 2025-10-07 00:13:41.401049 | controller | changed 2025-10-07 00:13:41.418259 | 2025-10-07 00:13:41.418460 | TASK [include_role : prepare-workspace] 2025-10-07 00:13:41.459789 | controller | ok 2025-10-07 00:13:41.502298 | 2025-10-07 00:13:41.502474 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-07 00:13:41.955397 | controller | ok 2025-10-07 00:13:41.964130 | 2025-10-07 00:13:41.964311 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-07 00:13:57.530811 | controller | Output suppressed because no_log was given 2025-10-07 00:13:57.556535 | 2025-10-07 00:13:57.556737 | TASK [include_role : prepare-workspace-openshift] 2025-10-07 00:13:57.584814 | controller | skipping: Conditional result was False 2025-10-07 00:13:57.630045 | 2025-10-07 00:13:57.630199 | PLAY [all:!appliance] 2025-10-07 00:13:57.699174 | 2025-10-07 00:13:57.699367 | TASK [Run add-build-sshkey role (RSA)] 2025-10-07 00:13:57.735433 | controller | ok 2025-10-07 00:13:57.756953 | 2025-10-07 00:13:57.757060 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-07 00:13:58.092052 | controller -> localhost | ok 2025-10-07 00:13:58.110362 | 2025-10-07 00:13:58.110553 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-07 00:13:58.151147 | controller | ok 2025-10-07 00:13:58.178529 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-07 00:13:58.186719 | 2025-10-07 00:13:58.186808 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-07 00:13:58.733755 | controller -> localhost | Generating public/private rsa key pair. 2025-10-07 00:13:58.733977 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_rsa. 2025-10-07 00:13:58.734007 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_rsa.pub. 2025-10-07 00:13:58.734029 | controller -> localhost | The key fingerprint is: 2025-10-07 00:13:58.734050 | controller -> localhost | SHA256:kXbVUU1vpB3cQcEJtYH5Jxrk/2ETae4mCYQ9JVaR8+U zuul-build-sshkey 2025-10-07 00:13:58.734071 | controller -> localhost | The key's randomart image is: 2025-10-07 00:13:58.734090 | controller -> localhost | +---[RSA 2048]----+ 2025-10-07 00:13:58.734109 | controller -> localhost | | o=%@X| 2025-10-07 00:13:58.734128 | controller -> localhost | | . +.*.BO| 2025-10-07 00:13:58.734147 | controller -> localhost | | + =oo =o*| 2025-10-07 00:13:58.734165 | controller -> localhost | | . + +o .BE| 2025-10-07 00:13:58.734184 | controller -> localhost | | S . .+o.o| 2025-10-07 00:13:58.734212 | controller -> localhost | | .. .= | 2025-10-07 00:13:58.734240 | controller -> localhost | | . +.o| 2025-10-07 00:13:58.734262 | controller -> localhost | | o o.| 2025-10-07 00:13:58.734282 | controller -> localhost | | o | 2025-10-07 00:13:58.734304 | controller -> localhost | +----[SHA256]-----+ 2025-10-07 00:13:58.734350 | controller -> localhost | ok: Runtime: 0:00:00.139195 2025-10-07 00:13:58.740817 | 2025-10-07 00:13:58.740885 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-07 00:13:58.773893 | controller | ok 2025-10-07 00:13:58.792223 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-07 00:13:58.801179 | 2025-10-07 00:13:58.801243 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-07 00:13:58.827470 | controller | skipping: Conditional result was False 2025-10-07 00:13:58.834651 | 2025-10-07 00:13:58.834735 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-07 00:13:59.495979 | controller | changed 2025-10-07 00:13:59.506482 | 2025-10-07 00:13:59.506615 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-07 00:13:59.847758 | controller | ok 2025-10-07 00:13:59.855982 | 2025-10-07 00:13:59.856082 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-07 00:14:01.207741 | controller | changed 2025-10-07 00:14:01.213838 | 2025-10-07 00:14:01.213903 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-07 00:14:02.899558 | controller | changed 2025-10-07 00:14:02.913040 | 2025-10-07 00:14:02.913178 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-07 00:14:02.940546 | controller | skipping: Conditional result was False 2025-10-07 00:14:02.956996 | 2025-10-07 00:14:02.957191 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-07 00:14:03.476977 | controller -> localhost | changed 2025-10-07 00:14:03.490296 | 2025-10-07 00:14:03.490421 | TASK [add-build-sshkey : Add back temp key] 2025-10-07 00:14:03.809394 | controller -> localhost | Identity added: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_rsa (zuul-build-sshkey) 2025-10-07 00:14:03.809734 | controller -> localhost | ok: Runtime: 0:00:00.012507 2025-10-07 00:14:03.816917 | 2025-10-07 00:14:03.816985 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-07 00:14:04.371914 | controller | ok 2025-10-07 00:14:04.377609 | 2025-10-07 00:14:04.377703 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-07 00:14:04.417787 | controller | skipping: Conditional result was False 2025-10-07 00:14:04.444850 | 2025-10-07 00:14:04.445053 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-07 00:14:04.478946 | controller | ok 2025-10-07 00:14:04.495271 | 2025-10-07 00:14:04.495404 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-07 00:14:04.796968 | controller -> localhost | ok 2025-10-07 00:14:04.808507 | 2025-10-07 00:14:04.808713 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-07 00:14:04.847380 | controller | ok 2025-10-07 00:14:04.866617 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-07 00:14:04.873227 | 2025-10-07 00:14:04.873361 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-07 00:14:05.291192 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-07 00:14:05.291464 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_ecdsa. 2025-10-07 00:14:05.291496 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_ecdsa.pub. 2025-10-07 00:14:05.291532 | controller -> localhost | The key fingerprint is: 2025-10-07 00:14:05.291553 | controller -> localhost | SHA256:pkYnbLBwDFxgRATqnLO1+r8RH/qWkTiY93tlnwHk+wQ zuul-build-sshkey 2025-10-07 00:14:05.291572 | controller -> localhost | The key's randomart image is: 2025-10-07 00:14:05.291610 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-07 00:14:05.291632 | controller -> localhost | |.*Bo. | 2025-10-07 00:14:05.291652 | controller -> localhost | |...o . | 2025-10-07 00:14:05.291698 | controller -> localhost | |. . + o | 2025-10-07 00:14:05.291721 | controller -> localhost | |o .o + E | 2025-10-07 00:14:05.291740 | controller -> localhost | | = .+.*.S + | 2025-10-07 00:14:05.291758 | controller -> localhost | | +o.*+B. + o | 2025-10-07 00:14:05.291775 | controller -> localhost | | . ..o=.o o + o | 2025-10-07 00:14:05.291793 | controller -> localhost | | . .o+ . + | 2025-10-07 00:14:05.291811 | controller -> localhost | | ....oooo | 2025-10-07 00:14:05.291828 | controller -> localhost | +----[SHA256]-----+ 2025-10-07 00:14:05.291888 | controller -> localhost | ok: Runtime: 0:00:00.017918 2025-10-07 00:14:05.299136 | 2025-10-07 00:14:05.299278 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-07 00:14:05.331819 | controller | ok 2025-10-07 00:14:05.339757 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-07 00:14:05.350638 | 2025-10-07 00:14:05.350795 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-07 00:14:05.375179 | controller | skipping: Conditional result was False 2025-10-07 00:14:05.382433 | 2025-10-07 00:14:05.382571 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-07 00:14:05.810198 | controller | changed 2025-10-07 00:14:05.817639 | 2025-10-07 00:14:05.818075 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-07 00:14:06.151957 | controller | ok 2025-10-07 00:14:06.159141 | 2025-10-07 00:14:06.159259 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-07 00:14:07.436220 | controller | changed 2025-10-07 00:14:07.446210 | 2025-10-07 00:14:07.446331 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-07 00:14:08.714235 | controller | changed 2025-10-07 00:14:08.721020 | 2025-10-07 00:14:08.721128 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-07 00:14:08.747506 | controller | skipping: Conditional result was False 2025-10-07 00:14:08.759112 | 2025-10-07 00:14:08.759291 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-07 00:14:09.072409 | controller -> localhost | changed 2025-10-07 00:14:09.084297 | 2025-10-07 00:14:09.084416 | TASK [add-build-sshkey : Add back temp key] 2025-10-07 00:14:09.344483 | controller -> localhost | Identity added: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/327130e19b7f4232b82b20f5642ca167_id_ecdsa (zuul-build-sshkey) 2025-10-07 00:14:09.344748 | controller -> localhost | ok: Runtime: 0:00:00.007110 2025-10-07 00:14:09.351220 | 2025-10-07 00:14:09.351293 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-07 00:14:09.701760 | controller | ok 2025-10-07 00:14:09.708936 | 2025-10-07 00:14:09.709026 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-07 00:14:09.733220 | controller | skipping: Conditional result was False 2025-10-07 00:14:09.744573 | 2025-10-07 00:14:09.744690 | TASK [include_role : remove-zuul-sshkey] 2025-10-07 00:14:09.768690 | controller | skipping: Conditional result was False 2025-10-07 00:14:09.776003 | 2025-10-07 00:14:09.776080 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-07 00:14:10.086055 | controller | ok: "logs" 2025-10-07 00:14:10.093756 | controller | ok: All items complete 2025-10-07 00:14:10.093836 | 2025-10-07 00:14:10.352735 | controller | ok: "artifacts" 2025-10-07 00:14:10.621090 | controller | ok: "docs" 2025-10-07 00:14:10.633417 | 2025-10-07 00:14:10.633521 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-07 00:14:10.942465 | controller | changed: "logs" 2025-10-07 00:14:11.218409 | controller | changed: "artifacts" 2025-10-07 00:14:11.496094 | controller | changed: "docs" 2025-10-07 00:14:11.536441 | 2025-10-07 00:14:11.536581 | PLAY RECAP 2025-10-07 00:14:11.536656 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-07 00:14:11.536728 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-07 00:14:11.536756 | 2025-10-07 00:14:11.673067 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-07 00:14:11.675328 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-07 00:14:12.250600 | 2025-10-07 00:14:12.250730 | PLAY [all] 2025-10-07 00:14:12.274421 | 2025-10-07 00:14:12.274545 | TASK [Install binary dependencies] 2025-10-07 00:14:12.330192 | controller | ok 2025-10-07 00:14:12.351200 | 2025-10-07 00:14:12.351326 | TASK [bindep : Include find tasks] 2025-10-07 00:14:12.380584 | controller | ok 2025-10-07 00:14:12.390011 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-07 00:14:12.396468 | 2025-10-07 00:14:12.396560 | TASK [bindep : Look for bindep.txt] 2025-10-07 00:14:12.922812 | controller | ok 2025-10-07 00:14:12.933305 | 2025-10-07 00:14:12.933453 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:14:12.959314 | controller | skipping: Conditional result was False 2025-10-07 00:14:12.968219 | 2025-10-07 00:14:12.968330 | TASK [bindep : Look for other-requirements.txt] 2025-10-07 00:14:13.243642 | controller | ok 2025-10-07 00:14:13.249231 | 2025-10-07 00:14:13.249311 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:14:13.284105 | controller | skipping: Conditional result was False 2025-10-07 00:14:13.293119 | 2025-10-07 00:14:13.293245 | TASK [bindep : Look for bindep fallback file] 2025-10-07 00:14:13.333418 | controller | skipping: Conditional result was False 2025-10-07 00:14:13.341701 | 2025-10-07 00:14:13.341874 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:14:13.370578 | controller | skipping: Conditional result was False 2025-10-07 00:14:13.380160 | 2025-10-07 00:14:13.380299 | TASK [bindep : Include bindep tasks] 2025-10-07 00:14:13.408655 | controller | skipping: Conditional result was False 2025-10-07 00:14:13.416244 | 2025-10-07 00:14:13.416430 | TASK [bindep : Include install tasks] 2025-10-07 00:14:13.440222 | controller | skipping: Conditional result was False 2025-10-07 00:14:13.446949 | 2025-10-07 00:14:13.447027 | LOOP [bindep : Include package tasks] 2025-10-07 00:14:13.505750 | 2025-10-07 00:14:13.505925 | TASK [Run test-setup role] 2025-10-07 00:14:13.525544 | controller | ok 2025-10-07 00:14:13.572185 | 2025-10-07 00:14:13.572383 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-07 00:14:13.882565 | controller | ok 2025-10-07 00:14:13.898321 | 2025-10-07 00:14:13.898518 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-07 00:14:14.044949 | controller | skipping: Conditional result was False 2025-10-07 00:14:14.081285 | 2025-10-07 00:14:14.081496 | PLAY RECAP 2025-10-07 00:14:14.081549 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-07 00:14:14.081571 | 2025-10-07 00:14:14.208232 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-07 00:14:14.209154 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-07 00:14:14.827528 | 2025-10-07 00:14:14.827685 | PLAY [controller] 2025-10-07 00:14:14.847362 | 2025-10-07 00:14:14.847484 | TASK [Create the /root directory] 2025-10-07 00:14:15.606437 | controller | ok 2025-10-07 00:14:15.616389 | 2025-10-07 00:14:15.616525 | TASK [Install glibc-langpack-en] 2025-10-07 00:14:23.548717 | controller | ok: Nothing to do 2025-10-07 00:14:23.558430 | 2025-10-07 00:14:23.558573 | TASK [Ensure controller directory exists] 2025-10-07 00:14:24.078768 | controller | changed 2025-10-07 00:14:24.086706 | 2025-10-07 00:14:24.086814 | TASK [Install container runtime] 2025-10-07 00:14:24.147018 | controller | ok 2025-10-07 00:14:24.201461 | 2025-10-07 00:14:24.201609 | LOOP [ensure-podman : Find distribution installation] 2025-10-07 00:14:24.245071 | controller | ok: "/var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-07 00:14:24.254281 | controller | included: /var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-07 00:14:24.288494 | 2025-10-07 00:14:24.288767 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-07 00:15:36.622027 | controller | changed 2025-10-07 00:15:36.634395 | 2025-10-07 00:15:36.634513 | TASK [ensure-podman : Fetch podman version] 2025-10-07 00:15:37.371779 | controller | Client: Podman Engine 2025-10-07 00:15:37.394076 | controller | Version: 4.6.2 2025-10-07 00:15:37.394123 | controller | API Version: 4.6.2 2025-10-07 00:15:37.394130 | controller | Go Version: go1.19.12 2025-10-07 00:15:37.394147 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-07 00:15:37.394154 | controller | OS/Arch: linux/amd64 2025-10-07 00:15:37.766377 | controller | ok: Runtime: 0:00:00.216087 2025-10-07 00:15:37.774393 | 2025-10-07 00:15:37.774502 | TASK [ensure-podman : Print podman version installed] 2025-10-07 00:15:37.803811 | Podman version: Client: Podman Engine 2025-10-07 00:15:37.804004 | Version: 4.6.2 2025-10-07 00:15:37.804039 | API Version: 4.6.2 2025-10-07 00:15:37.804062 | Go Version: go1.19.12 2025-10-07 00:15:37.804083 | Built: Mon Aug 28 19:38:31 2023 2025-10-07 00:15:37.804105 | OS/Arch: linux/amd64 2025-10-07 00:15:37.815196 | 2025-10-07 00:15:37.815413 | TASK [ensure-podman : Validate podman engine] 2025-10-07 00:15:37.946730 | controller | skipping: Conditional result was False 2025-10-07 00:15:37.955750 | 2025-10-07 00:15:37.955856 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-07 00:15:37.982264 | controller | skipping: Conditional result was False 2025-10-07 00:15:38.005109 | 2025-10-07 00:15:38.005257 | TASK [Ensure python3.8 is present] 2025-10-07 00:15:38.020523 | controller | skipping: Conditional result was False 2025-10-07 00:15:38.027489 | 2025-10-07 00:15:38.027599 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-07 00:15:38.047090 | controller | ok 2025-10-07 00:15:38.070122 | 2025-10-07 00:15:38.070264 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-07 00:15:42.100496 | controller | ok: Nothing to do 2025-10-07 00:15:42.109910 | 2025-10-07 00:15:42.110041 | TASK [our-ensure-python : Also install python3-devel] 2025-10-07 00:15:54.895132 | controller | changed 2025-10-07 00:15:54.918544 | 2025-10-07 00:15:54.918739 | TASK [Run ensure-virtualenv role] 2025-10-07 00:15:54.947470 | controller | ok 2025-10-07 00:15:54.993391 | 2025-10-07 00:15:54.993499 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-07 00:15:55.356864 | controller | /usr/bin/virtualenv 2025-10-07 00:15:55.628257 | controller | ok: Runtime: 0:00:00.004697 2025-10-07 00:15:55.641356 | 2025-10-07 00:15:55.641557 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-07 00:15:55.682125 | controller | skipping: Conditional result was False 2025-10-07 00:15:55.682634 | controller | ok: All items complete 2025-10-07 00:15:55.682740 | 2025-10-07 00:15:55.714846 | 2025-10-07 00:15:55.715058 | TASK [Find the full path of the Python interpreter] 2025-10-07 00:15:56.119079 | controller | /usr/bin/python3 2025-10-07 00:15:56.405080 | controller | ok 2025-10-07 00:15:56.419835 | 2025-10-07 00:15:56.420186 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-07 00:15:57.855419 | controller | created virtual environment CPython3.11.0.final.0-64 in 724ms 2025-10-07 00:15:57.894741 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-07 00:15:57.894800 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv) 2025-10-07 00:15:57.894818 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-07 00:15:57.894841 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-07 00:15:58.092102 | controller | changed 2025-10-07 00:15:58.100859 | 2025-10-07 00:15:58.100952 | TASK [Set selinux package] 2025-10-07 00:15:58.123564 | controller | ok 2025-10-07 00:15:58.134832 | 2025-10-07 00:15:58.134937 | TASK [Set selinux package (Fedora)] 2025-10-07 00:15:58.176529 | controller | ok 2025-10-07 00:15:58.185483 | 2025-10-07 00:15:58.185571 | TASK [Install selinux into virtualenv] 2025-10-07 00:16:00.770398 | controller | Collecting selinux-please-lie-to-me 2025-10-07 00:16:00.859638 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-07 00:16:01.395069 | controller | Collecting setuptools<50.0.0 2025-10-07 00:16:01.408598 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-07 00:16:01.547599 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.1 MB/s eta 0:00:00 2025-10-07 00:16:01.694296 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-07 00:16:01.694709 | controller | Attempting uninstall: setuptools 2025-10-07 00:16:01.699727 | controller | Found existing installation: setuptools 62.6.0 2025-10-07 00:16:01.812415 | controller | Uninstalling setuptools-62.6.0: 2025-10-07 00:16:01.827864 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-07 00:16:02.612808 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-07 00:16:02.823447 | controller | 2025-10-07 00:16:03.029278 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-07 00:16:03.029330 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-07 00:16:03.326829 | controller | ok: Runtime: 0:00:04.371613 2025-10-07 00:16:03.332407 | 2025-10-07 00:16:03.332528 | TASK [Install pytest-forked into virtualenv] 2025-10-07 00:16:04.501713 | controller | Collecting pytest-forked 2025-10-07 00:16:04.589435 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-07 00:16:04.648978 | controller | Collecting py 2025-10-07 00:16:04.661539 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-07 00:16:04.699752 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-10-07 00:16:04.873635 | controller | Collecting pytest>=3.10 2025-10-07 00:16:04.886568 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-07 00:16:04.952444 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.8 MB/s eta 0:00:00 2025-10-07 00:16:05.004617 | controller | Collecting iniconfig>=1 2025-10-07 00:16:05.017845 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-07 00:16:05.084249 | controller | Collecting packaging>=20 2025-10-07 00:16:05.096817 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-07 00:16:05.109827 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.0 MB/s eta 0:00:00 2025-10-07 00:16:05.157806 | controller | Collecting pluggy<2,>=1.5 2025-10-07 00:16:05.171922 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-07 00:16:05.246440 | controller | Collecting pygments>=2.7.2 2025-10-07 00:16:05.259240 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-07 00:16:05.392963 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.4 MB/s eta 0:00:00 2025-10-07 00:16:05.553392 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-07 00:16:07.815555 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-10-07 00:16:07.832169 | controller | 2025-10-07 00:16:08.003849 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-07 00:16:08.003902 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-07 00:16:08.515233 | controller | ok: Runtime: 0:00:04.220626 2025-10-07 00:16:08.528334 | 2025-10-07 00:16:08.528487 | TASK [Update pip] 2025-10-07 00:16:09.618476 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-07 00:16:09.889553 | controller | Collecting pip 2025-10-07 00:16:09.992665 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-07 00:16:10.109711 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 15.6 MB/s eta 0:00:00 2025-10-07 00:16:10.276339 | controller | Installing collected packages: pip 2025-10-07 00:16:10.277029 | controller | Attempting uninstall: pip 2025-10-07 00:16:10.284222 | controller | Found existing installation: pip 22.2.2 2025-10-07 00:16:10.613090 | controller | Uninstalling pip-22.2.2: 2025-10-07 00:16:10.646170 | controller | Successfully uninstalled pip-22.2.2 2025-10-07 00:16:12.392536 | controller | Successfully installed pip-25.2 2025-10-07 00:16:12.690975 | controller | ok: Runtime: 0:00:03.556689 2025-10-07 00:16:12.706167 | 2025-10-07 00:16:12.706346 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-07 00:16:13.253966 | controller | changed 2025-10-07 00:16:13.265197 | 2025-10-07 00:16:13.265352 | TASK [Install ansible into virtualenv] 2025-10-07 00:16:14.339932 | controller | Processing ./src/github.com/ansible/ansible 2025-10-07 00:16:14.346480 | controller | Installing build dependencies: started 2025-10-07 00:16:16.290090 | controller | Installing build dependencies: finished with status 'done' 2025-10-07 00:16:16.290978 | controller | Getting requirements to build wheel: started 2025-10-07 00:16:17.806161 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-07 00:16:17.807555 | controller | Preparing metadata (pyproject.toml): started 2025-10-07 00:16:18.719090 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-07 00:16:18.723906 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-10-07 00:16:18.728659 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-07 00:16:18.955031 | controller | ERROR 2025-10-07 00:16:18.955301 | controller | { 2025-10-07 00:16:18.955359 | controller | "delta": "0:00:05.155994", 2025-10-07 00:16:18.955400 | controller | "end": "2025-10-07 00:16:18.873837", 2025-10-07 00:16:18.955436 | controller | "msg": "non-zero return code", 2025-10-07 00:16:18.955487 | controller | "rc": 1, 2025-10-07 00:16:18.955524 | controller | "start": "2025-10-07 00:16:13.717843" 2025-10-07 00:16:18.955557 | controller | } failure 2025-10-07 00:16:18.958500 | 2025-10-07 00:16:18.958616 | PLAY RECAP 2025-10-07 00:16:18.958739 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-07 00:16:18.958791 | 2025-10-07 00:16:19.089887 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-07 00:16:19.092147 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-07 00:16:19.698827 | 2025-10-07 00:16:19.698986 | PLAY [all] 2025-10-07 00:16:19.720300 | 2025-10-07 00:16:19.720437 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-07 00:16:20.521234 | controller | changed: non-zero return code 2025-10-07 00:16:20.529279 | 2025-10-07 00:16:20.529450 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-07 00:16:20.544998 | controller | skipping: Conditional result was False 2025-10-07 00:16:20.553483 | 2025-10-07 00:16:20.553706 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-07 00:16:20.588501 | 2025-10-07 00:16:20.588724 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-07 00:16:20.619951 | 2025-10-07 00:16:20.620118 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-07 00:16:20.635191 | controller | skipping: Conditional result was False 2025-10-07 00:16:20.642315 | 2025-10-07 00:16:20.642388 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-07 00:16:20.687758 | 2025-10-07 00:16:20.687993 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-07 00:16:20.706073 | controller | skipping: Conditional result was False 2025-10-07 00:16:20.713235 | 2025-10-07 00:16:20.713319 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-07 00:16:20.750654 | controller | skipping: Conditional result was False 2025-10-07 00:16:20.756920 | 2025-10-07 00:16:20.757017 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-07 00:16:20.770991 | controller | skipping: Conditional result was False 2025-10-07 00:16:20.822172 | 2025-10-07 00:16:20.822278 | PLAY RECAP 2025-10-07 00:16:20.822321 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-07 00:16:20.822342 | 2025-10-07 00:16:20.916396 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-07 00:16:20.917279 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-07 00:16:21.525703 | 2025-10-07 00:16:21.525822 | PLAY [all:!appliance*] 2025-10-07 00:16:21.551893 | 2025-10-07 00:16:21.552005 | TASK [unregister the node] 2025-10-07 00:16:21.684434 | controller | skipping: Conditional result was False 2025-10-07 00:16:21.693045 | 2025-10-07 00:16:21.693199 | TASK [include_role : fetch-output] 2025-10-07 00:16:21.726048 | controller | ok 2025-10-07 00:16:21.748047 | 2025-10-07 00:16:21.748178 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-07 00:16:21.813747 | controller | skipping: Conditional result was False 2025-10-07 00:16:21.825933 | 2025-10-07 00:16:21.826098 | TASK [fetch-output : Set log path for single node] 2025-10-07 00:16:21.857620 | controller | ok 2025-10-07 00:16:21.863420 | 2025-10-07 00:16:21.863504 | LOOP [fetch-output : Ensure local output dirs] 2025-10-07 00:16:22.240553 | controller -> localhost | ok: "/var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/logs" 2025-10-07 00:16:22.465437 | controller -> localhost | changed: "/var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/artifacts" 2025-10-07 00:16:22.821838 | controller -> localhost | changed: "/var/lib/zuul/builds/327130e19b7f4232b82b20f5642ca167/work/docs" 2025-10-07 00:16:22.839187 | 2025-10-07 00:16:22.839300 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-07 00:16:24.136992 | controller | changed: 2025-10-07 00:16:24.137204 | controller | .d..t...... ./ 2025-10-07 00:16:24.137233 | controller | cd+++++++++ controller/ 2025-10-07 00:16:24.137268 | controller | changed: All items complete 2025-10-07 00:16:24.137289 | 2025-10-07 00:16:25.095742 | controller | changed: .d..t...... ./ 2025-10-07 00:16:26.090268 | controller | changed: .d..t...... ./ 2025-10-07 00:16:26.118086 | 2025-10-07 00:16:26.118199 | TASK [include_role : fetch-output-openshift] 2025-10-07 00:16:26.142741 | controller | skipping: Conditional result was False 2025-10-07 00:16:26.148890 | 2025-10-07 00:16:26.148972 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-07 00:16:26.175472 | controller | skipping: Conditional result was False 2025-10-07 00:16:26.184123 | controller | skipping: Conditional result was False 2025-10-07 00:16:26.220633 | 2025-10-07 00:16:26.220765 | PLAY [localhost] 2025-10-07 00:16:26.233796 | 2025-10-07 00:16:26.233886 | TASK [Run Zuul manifest role] 2025-10-07 00:16:26.252321 | localhost | ok 2025-10-07 00:16:26.269757 | 2025-10-07 00:16:26.269875 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-07 00:16:26.629621 | localhost | changed 2025-10-07 00:16:26.636631 | 2025-10-07 00:16:26.636754 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-07 00:16:26.668357 | localhost | ok 2025-10-07 00:16:26.680033 | 2025-10-07 00:16:26.680117 | TASK [Set zuul-log-path fact] 2025-10-07 00:16:26.702123 | localhost | ok 2025-10-07 00:16:26.721460 | 2025-10-07 00:16:26.721559 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-07 00:16:26.763124 | localhost | ok 2025-10-07 00:16:26.776100 | 2025-10-07 00:16:26.776187 | LOOP [Run upload-logs-swift role] 2025-10-07 00:16:26.800732 | localhost | Output suppressed because no_log was given 2025-10-07 00:16:26.838225 | 2025-10-07 00:16:26.838338 | TASK [Set zuul-log-path fact] 2025-10-07 00:16:26.873804 | localhost | skipping: Conditional result was False 2025-10-07 00:16:26.880914 | 2025-10-07 00:16:26.881013 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-07 00:16:27.348643 | localhost -> localhost | ok: Runtime: 0:00:00.027376 2025-10-07 00:16:27.354225 | 2025-10-07 00:16:27.354286 | TASK [upload-logs-swift : Upload logs to swift]