2025-09-25 00:06:33.304538 | Job console starting... 2025-09-25 00:06:33.320362 | Updating repositories 2025-09-25 00:06:33.983675 | Preparing job workspace 2025-09-25 00:06:37.727918 | Running Ansible setup... 2025-09-25 00:06:43.392312 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-25 00:06:44.030788 | 2025-09-25 00:06:44.030902 | PLAY [localhost] 2025-09-25 00:06:44.039046 | 2025-09-25 00:06:44.039116 | TASK [Gathering Facts] 2025-09-25 00:06:45.107977 | localhost | ok 2025-09-25 00:06:45.140729 | 2025-09-25 00:06:45.140994 | TASK [Setup log path fact] 2025-09-25 00:06:45.181613 | localhost | ok 2025-09-25 00:06:45.207907 | 2025-09-25 00:06:45.208040 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-25 00:06:45.239196 | localhost | ok 2025-09-25 00:06:45.250455 | 2025-09-25 00:06:45.250585 | TASK [emit-job-header : Print job information] 2025-09-25 00:06:45.293630 | # Job Information 2025-09-25 00:06:45.293835 | Ansible Version: 2.15.12 2025-09-25 00:06:45.293899 | Job: ansible-test-sanity-docker-milestone 2025-09-25 00:06:45.293959 | Pipeline: periodic 2025-09-25 00:06:45.294005 | Executor: ze01.softwarefactory-project.io 2025-09-25 00:06:45.294086 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-25 00:06:45.294135 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/c91/ansible/c91ec58183774daf8d5cddd964621bb3/ 2025-09-25 00:06:45.294178 | Event ID: 21226ec8c3ac40f2b6f018dec2056d83 2025-09-25 00:06:45.301549 | 2025-09-25 00:06:45.301666 | LOOP [emit-job-header : Print node information] 2025-09-25 00:06:45.425101 | localhost | ok: 2025-09-25 00:06:45.425260 | localhost | # Node Information 2025-09-25 00:06:45.425289 | localhost | Inventory Hostname: controller 2025-09-25 00:06:45.425311 | localhost | Hostname: ip-172-16-77-7 2025-09-25 00:06:45.425332 | localhost | Username: zuul-worker 2025-09-25 00:06:45.425355 | localhost | Distro: Fedora 37 2025-09-25 00:06:45.425374 | localhost | Provider: ansible-us-east-2 2025-09-25 00:06:45.425393 | localhost | Region: us-east-2 2025-09-25 00:06:45.425412 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-25 00:06:45.425430 | localhost | Product Name: t3.small 2025-09-25 00:06:45.425449 | localhost | Interface IP: 18.216.142.147 2025-09-25 00:06:45.437084 | 2025-09-25 00:06:45.437151 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-25 00:06:45.847278 | localhost -> localhost | changed 2025-09-25 00:06:45.852883 | 2025-09-25 00:06:45.852967 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-25 00:06:46.743473 | localhost -> localhost | changed 2025-09-25 00:06:46.785687 | 2025-09-25 00:06:46.785870 | PLAY [all:!appliance*] 2025-09-25 00:06:46.816514 | 2025-09-25 00:06:46.816647 | TASK [include_role : start-zuul-console] 2025-09-25 00:06:46.837794 | controller | ok 2025-09-25 00:06:46.857063 | 2025-09-25 00:06:46.857189 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-25 00:06:47.534672 | controller | ok 2025-09-25 00:06:47.553509 | 2025-09-25 00:06:47.553713 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-25 00:06:48.900916 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-25 00:06:48.940911 | 2025-09-25 00:06:48.941123 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-25 00:06:49.082926 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.090936 | 2025-09-25 00:06:49.091096 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-25 00:06:49.126512 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.135149 | 2025-09-25 00:06:49.135278 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-25 00:06:49.170801 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.178727 | 2025-09-25 00:06:49.178884 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-25 00:06:49.214919 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.221160 | 2025-09-25 00:06:49.221383 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-25 00:06:49.246413 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.256318 | 2025-09-25 00:06:49.256455 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-25 00:06:49.281516 | controller | skipping: Conditional result was False 2025-09-25 00:06:49.300616 | 2025-09-25 00:06:49.300770 | TASK [Disable Fedora Modular] 2025-09-25 00:06:50.025269 | controller | changed 2025-09-25 00:06:50.038158 | 2025-09-25 00:06:50.038342 | TASK [Enable EPEL] 2025-09-25 00:06:50.066955 | controller | skipping: Conditional result was False 2025-09-25 00:06:50.082063 | 2025-09-25 00:06:50.082241 | TASK [Register the RHEL node] 2025-09-25 00:06:50.240509 | 2025-09-25 00:06:50.240787 | TASK [Show the subscription-manager status] 2025-09-25 00:06:50.392275 | controller | skipping: Conditional result was False 2025-09-25 00:06:50.424252 | 2025-09-25 00:06:50.424356 | TASK [Enable EPEL on RHEL] 2025-09-25 00:06:50.560181 | controller | skipping: Conditional result was False 2025-09-25 00:06:50.568442 | 2025-09-25 00:06:50.568540 | TASK [Install git and tox] 2025-09-25 00:08:24.957675 | controller | changed 2025-09-25 00:08:24.967655 | 2025-09-25 00:08:24.967756 | TASK [include_role : prepare-workspace] 2025-09-25 00:08:25.001785 | controller | ok 2025-09-25 00:08:25.034140 | 2025-09-25 00:08:25.034287 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-25 00:08:25.625162 | controller | ok 2025-09-25 00:08:25.631463 | 2025-09-25 00:08:25.631534 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-25 00:08:38.020385 | controller | Output suppressed because no_log was given 2025-09-25 00:08:38.033285 | 2025-09-25 00:08:38.033397 | TASK [include_role : prepare-workspace-openshift] 2025-09-25 00:08:38.057632 | controller | skipping: Conditional result was False 2025-09-25 00:08:38.079767 | 2025-09-25 00:08:38.079852 | PLAY [all:!appliance] 2025-09-25 00:08:38.095115 | 2025-09-25 00:08:38.095215 | TASK [Run add-build-sshkey role (RSA)] 2025-09-25 00:08:38.126893 | controller | ok 2025-09-25 00:08:38.141526 | 2025-09-25 00:08:38.141645 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-25 00:08:38.424360 | controller -> localhost | ok 2025-09-25 00:08:38.475345 | 2025-09-25 00:08:38.475485 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-25 00:08:38.510180 | controller | ok 2025-09-25 00:08:38.530406 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-25 00:08:38.539999 | 2025-09-25 00:08:38.540109 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-25 00:08:39.198673 | controller -> localhost | Generating public/private rsa key pair. 2025-09-25 00:08:39.198877 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_rsa. 2025-09-25 00:08:39.198912 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_rsa.pub. 2025-09-25 00:08:39.198937 | controller -> localhost | The key fingerprint is: 2025-09-25 00:08:39.198961 | controller -> localhost | SHA256:kI6maKOcZE9K28TwsrJNYbqvF9YwaLaDPYVNAdJ/c4M zuul-build-sshkey 2025-09-25 00:08:39.198984 | controller -> localhost | The key's randomart image is: 2025-09-25 00:08:39.199006 | controller -> localhost | +---[RSA 2048]----+ 2025-09-25 00:08:39.199052 | controller -> localhost | |...... | 2025-09-25 00:08:39.199103 | controller -> localhost | | .. . . | 2025-09-25 00:08:39.199124 | controller -> localhost | | . = o. | 2025-09-25 00:08:39.199142 | controller -> localhost | |.o+ +oE.o | 2025-09-25 00:08:39.199160 | controller -> localhost | |+o+=o..oS. | 2025-09-25 00:08:39.199198 | controller -> localhost | |.*O+. | 2025-09-25 00:08:39.199221 | controller -> localhost | |oO+B | 2025-09-25 00:08:39.199243 | controller -> localhost | |O+& | 2025-09-25 00:08:39.199270 | controller -> localhost | |*@oo | 2025-09-25 00:08:39.199291 | controller -> localhost | +----[SHA256]-----+ 2025-09-25 00:08:39.199337 | controller -> localhost | ok: Runtime: 0:00:00.196852 2025-09-25 00:08:39.206083 | 2025-09-25 00:08:39.206149 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-25 00:08:39.236821 | controller | ok 2025-09-25 00:08:39.247280 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-25 00:08:39.256461 | 2025-09-25 00:08:39.256527 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-25 00:08:39.271059 | controller | skipping: Conditional result was False 2025-09-25 00:08:39.278627 | 2025-09-25 00:08:39.278708 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-25 00:08:40.241656 | controller | changed 2025-09-25 00:08:40.256572 | 2025-09-25 00:08:40.256741 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-25 00:08:40.654651 | controller | ok 2025-09-25 00:08:40.667580 | 2025-09-25 00:08:40.667841 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-25 00:08:41.951150 | controller | changed 2025-09-25 00:08:41.958625 | 2025-09-25 00:08:41.958719 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-25 00:08:43.309117 | controller | changed 2025-09-25 00:08:43.317899 | 2025-09-25 00:08:43.318138 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-25 00:08:43.345908 | controller | skipping: Conditional result was False 2025-09-25 00:08:43.359566 | 2025-09-25 00:08:43.359701 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-25 00:08:43.784729 | controller -> localhost | changed 2025-09-25 00:08:43.795439 | 2025-09-25 00:08:43.795509 | TASK [add-build-sshkey : Add back temp key] 2025-09-25 00:08:44.156927 | controller -> localhost | Identity added: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_rsa (zuul-build-sshkey) 2025-09-25 00:08:44.157250 | controller -> localhost | ok: Runtime: 0:00:00.008127 2025-09-25 00:08:44.165817 | 2025-09-25 00:08:44.165903 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-25 00:08:44.682803 | controller | ok 2025-09-25 00:08:44.695273 | 2025-09-25 00:08:44.695420 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-25 00:08:44.733044 | controller | skipping: Conditional result was False 2025-09-25 00:08:44.759085 | 2025-09-25 00:08:44.759261 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-25 00:08:44.793512 | controller | ok 2025-09-25 00:08:44.817554 | 2025-09-25 00:08:44.817688 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-25 00:08:45.097211 | controller -> localhost | ok 2025-09-25 00:08:45.103608 | 2025-09-25 00:08:45.103670 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-25 00:08:45.133817 | controller | ok 2025-09-25 00:08:45.144158 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-25 00:08:45.149721 | 2025-09-25 00:08:45.149782 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-25 00:08:45.489661 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-25 00:08:45.489980 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_ecdsa. 2025-09-25 00:08:45.490135 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_ecdsa.pub. 2025-09-25 00:08:45.490208 | controller -> localhost | The key fingerprint is: 2025-09-25 00:08:45.490258 | controller -> localhost | SHA256:us7fPc/pbkrdtyo0JGTNn1LzYCXN2dbYtfB/94Rfj+w zuul-build-sshkey 2025-09-25 00:08:45.490305 | controller -> localhost | The key's randomart image is: 2025-09-25 00:08:45.490348 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-25 00:08:45.490391 | controller -> localhost | | o o++*| 2025-09-25 00:08:45.490435 | controller -> localhost | | o o ==+*| 2025-09-25 00:08:45.490478 | controller -> localhost | | o + =+ | 2025-09-25 00:08:45.490519 | controller -> localhost | | . o o o.| 2025-09-25 00:08:45.490561 | controller -> localhost | | S o . . *| 2025-09-25 00:08:45.490617 | controller -> localhost | | . o o =*| 2025-09-25 00:08:45.490681 | controller -> localhost | | . . o + *| 2025-09-25 00:08:45.490757 | controller -> localhost | | . . . +.o..o| 2025-09-25 00:08:45.490822 | controller -> localhost | | .+.. . +OE. | 2025-09-25 00:08:45.490868 | controller -> localhost | +----[SHA256]-----+ 2025-09-25 00:08:45.490972 | controller -> localhost | ok: Runtime: 0:00:00.014361 2025-09-25 00:08:45.505417 | 2025-09-25 00:08:45.505561 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-25 00:08:45.540654 | controller | ok 2025-09-25 00:08:45.550958 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-25 00:08:45.564102 | 2025-09-25 00:08:45.564192 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-25 00:08:45.589470 | controller | skipping: Conditional result was False 2025-09-25 00:08:45.598834 | 2025-09-25 00:08:45.598935 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-25 00:08:46.064795 | controller | changed 2025-09-25 00:08:46.077294 | 2025-09-25 00:08:46.077424 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-25 00:08:46.432930 | controller | ok 2025-09-25 00:08:46.446941 | 2025-09-25 00:08:46.447116 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-25 00:08:47.681486 | controller | changed 2025-09-25 00:08:47.693779 | 2025-09-25 00:08:47.693912 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-25 00:08:48.941984 | controller | changed 2025-09-25 00:08:48.955296 | 2025-09-25 00:08:48.955429 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-25 00:08:48.983871 | controller | skipping: Conditional result was False 2025-09-25 00:08:49.000209 | 2025-09-25 00:08:49.000367 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-25 00:08:49.272930 | controller -> localhost | changed 2025-09-25 00:08:49.297747 | 2025-09-25 00:08:49.297894 | TASK [add-build-sshkey : Add back temp key] 2025-09-25 00:08:49.630929 | controller -> localhost | Identity added: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/c91ec58183774daf8d5cddd964621bb3_id_ecdsa (zuul-build-sshkey) 2025-09-25 00:08:49.631195 | controller -> localhost | ok: Runtime: 0:00:00.012820 2025-09-25 00:08:49.637484 | 2025-09-25 00:08:49.637546 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-25 00:08:49.966198 | controller | ok 2025-09-25 00:08:49.973491 | 2025-09-25 00:08:49.973580 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-25 00:08:50.018781 | controller | skipping: Conditional result was False 2025-09-25 00:08:50.034004 | 2025-09-25 00:08:50.034140 | TASK [include_role : remove-zuul-sshkey] 2025-09-25 00:08:50.058824 | controller | skipping: Conditional result was False 2025-09-25 00:08:50.068160 | 2025-09-25 00:08:50.068285 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-25 00:08:50.394784 | controller | ok: "logs" 2025-09-25 00:08:50.395350 | controller | ok: All items complete 2025-09-25 00:08:50.395418 | 2025-09-25 00:08:50.705785 | controller | ok: "artifacts" 2025-09-25 00:08:50.960413 | controller | ok: "docs" 2025-09-25 00:08:50.974632 | 2025-09-25 00:08:50.974754 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-25 00:08:51.345900 | controller | changed: "logs" 2025-09-25 00:08:51.654761 | controller | changed: "artifacts" 2025-09-25 00:08:51.962292 | controller | changed: "docs" 2025-09-25 00:08:52.018683 | 2025-09-25 00:08:52.018819 | PLAY RECAP 2025-09-25 00:08:52.018883 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-25 00:08:52.018918 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-25 00:08:52.018942 | 2025-09-25 00:08:52.136776 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-25 00:08:52.137631 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-25 00:08:52.704708 | 2025-09-25 00:08:52.704811 | PLAY [all] 2025-09-25 00:08:52.726267 | 2025-09-25 00:08:52.726366 | TASK [Install binary dependencies] 2025-09-25 00:08:52.778811 | controller | ok 2025-09-25 00:08:52.798252 | 2025-09-25 00:08:52.798360 | TASK [bindep : Include find tasks] 2025-09-25 00:08:52.827296 | controller | ok 2025-09-25 00:08:52.834926 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-25 00:08:52.841127 | 2025-09-25 00:08:52.841193 | TASK [bindep : Look for bindep.txt] 2025-09-25 00:08:53.338665 | controller | ok 2025-09-25 00:08:53.359226 | 2025-09-25 00:08:53.359415 | TASK [bindep : Define bindep_file fact] 2025-09-25 00:08:53.386546 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.395705 | 2025-09-25 00:08:53.395810 | TASK [bindep : Look for other-requirements.txt] 2025-09-25 00:08:53.706331 | controller | ok 2025-09-25 00:08:53.717989 | 2025-09-25 00:08:53.718188 | TASK [bindep : Define bindep_file fact] 2025-09-25 00:08:53.755425 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.768820 | 2025-09-25 00:08:53.768958 | TASK [bindep : Look for bindep fallback file] 2025-09-25 00:08:53.806332 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.830593 | 2025-09-25 00:08:53.830764 | TASK [bindep : Define bindep_file fact] 2025-09-25 00:08:53.857216 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.869405 | 2025-09-25 00:08:53.869538 | TASK [bindep : Include bindep tasks] 2025-09-25 00:08:53.906383 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.923052 | 2025-09-25 00:08:53.923216 | TASK [bindep : Include install tasks] 2025-09-25 00:08:53.949294 | controller | skipping: Conditional result was False 2025-09-25 00:08:53.962531 | 2025-09-25 00:08:53.962690 | LOOP [bindep : Include package tasks] 2025-09-25 00:08:54.038804 | 2025-09-25 00:08:54.039408 | TASK [Run test-setup role] 2025-09-25 00:08:54.064168 | controller | ok 2025-09-25 00:08:54.089912 | 2025-09-25 00:08:54.090112 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-25 00:08:54.380527 | controller | ok 2025-09-25 00:08:54.393585 | 2025-09-25 00:08:54.393722 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-25 00:08:54.542422 | controller | skipping: Conditional result was False 2025-09-25 00:08:54.577324 | 2025-09-25 00:08:54.577435 | PLAY RECAP 2025-09-25 00:08:54.577489 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-25 00:08:54.577518 | 2025-09-25 00:08:54.677298 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-25 00:08:54.679418 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-25 00:08:55.326539 | 2025-09-25 00:08:55.326661 | PLAY [controller] 2025-09-25 00:08:55.346554 | 2025-09-25 00:08:55.346646 | TASK [Create the /root directory] 2025-09-25 00:08:56.102528 | controller | ok 2025-09-25 00:08:56.111169 | 2025-09-25 00:08:56.111288 | TASK [Install glibc-langpack-en] 2025-09-25 00:09:06.452540 | controller | ok: Nothing to do 2025-09-25 00:09:06.465173 | 2025-09-25 00:09:06.465337 | TASK [Ensure controller directory exists] 2025-09-25 00:09:06.895553 | controller | changed 2025-09-25 00:09:06.909287 | 2025-09-25 00:09:06.909474 | TASK [Install container runtime] 2025-09-25 00:09:06.990219 | controller | ok 2025-09-25 00:09:07.048803 | 2025-09-25 00:09:07.048951 | LOOP [ensure-podman : Find distribution installation] 2025-09-25 00:09:07.097065 | controller | ok: "/var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-25 00:09:07.113073 | controller | included: /var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-25 00:09:07.123427 | 2025-09-25 00:09:07.123575 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-25 00:10:28.590990 | controller | changed 2025-09-25 00:10:28.604235 | 2025-09-25 00:10:28.604367 | TASK [ensure-podman : Fetch podman version] 2025-09-25 00:10:29.497647 | controller | Client: Podman Engine 2025-09-25 00:10:29.523834 | controller | Version: 4.6.2 2025-09-25 00:10:29.523879 | controller | API Version: 4.6.2 2025-09-25 00:10:29.523888 | controller | Go Version: go1.19.12 2025-09-25 00:10:29.523906 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-25 00:10:29.523914 | controller | OS/Arch: linux/amd64 2025-09-25 00:10:29.748094 | controller | ok: Runtime: 0:00:00.250231 2025-09-25 00:10:29.756564 | 2025-09-25 00:10:29.756665 | TASK [ensure-podman : Print podman version installed] 2025-09-25 00:10:29.786506 | Podman version: Client: Podman Engine 2025-09-25 00:10:29.786681 | Version: 4.6.2 2025-09-25 00:10:29.786712 | API Version: 4.6.2 2025-09-25 00:10:29.786733 | Go Version: go1.19.12 2025-09-25 00:10:29.786751 | Built: Mon Aug 28 19:38:31 2023 2025-09-25 00:10:29.786771 | OS/Arch: linux/amd64 2025-09-25 00:10:29.792175 | 2025-09-25 00:10:29.792250 | TASK [ensure-podman : Validate podman engine] 2025-09-25 00:10:29.920588 | controller | skipping: Conditional result was False 2025-09-25 00:10:29.934105 | 2025-09-25 00:10:29.934258 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-25 00:10:29.961237 | controller | skipping: Conditional result was False 2025-09-25 00:10:29.984428 | 2025-09-25 00:10:29.984565 | TASK [Ensure python3.8 is present] 2025-09-25 00:10:30.011268 | controller | skipping: Conditional result was False 2025-09-25 00:10:30.024170 | 2025-09-25 00:10:30.024302 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-25 00:10:30.058516 | controller | ok 2025-09-25 00:10:30.089618 | 2025-09-25 00:10:30.089766 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-25 00:10:33.854480 | controller | ok: Nothing to do 2025-09-25 00:10:33.862070 | 2025-09-25 00:10:33.862195 | TASK [our-ensure-python : Also install python3-devel] 2025-09-25 00:10:47.389317 | controller | changed 2025-09-25 00:10:47.400367 | 2025-09-25 00:10:47.400479 | TASK [Run ensure-virtualenv role] 2025-09-25 00:10:47.420703 | controller | ok 2025-09-25 00:10:47.442879 | 2025-09-25 00:10:47.443051 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-25 00:10:47.790213 | controller | /usr/bin/virtualenv 2025-09-25 00:10:48.076380 | controller | ok: Runtime: 0:00:00.004918 2025-09-25 00:10:48.085264 | 2025-09-25 00:10:48.086250 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-25 00:10:48.126563 | controller | skipping: Conditional result was False 2025-09-25 00:10:48.126862 | controller | ok: All items complete 2025-09-25 00:10:48.126897 | 2025-09-25 00:10:48.149894 | 2025-09-25 00:10:48.150076 | TASK [Find the full path of the Python interpreter] 2025-09-25 00:10:48.605132 | controller | /usr/bin/python3 2025-09-25 00:10:48.810331 | controller | ok 2025-09-25 00:10:48.816149 | 2025-09-25 00:10:48.816219 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-25 00:10:50.177770 | controller | created virtual environment CPython3.11.0.final.0-64 in 764ms 2025-09-25 00:10:50.219499 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-25 00:10:50.219558 | 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-09-25 00:10:50.219576 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-25 00:10:50.219601 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-25 00:10:50.444243 | controller | changed 2025-09-25 00:10:50.456649 | 2025-09-25 00:10:50.456795 | TASK [Set selinux package] 2025-09-25 00:10:50.484353 | controller | ok 2025-09-25 00:10:50.495490 | 2025-09-25 00:10:50.495653 | TASK [Set selinux package (Fedora)] 2025-09-25 00:10:50.543345 | controller | ok 2025-09-25 00:10:50.553965 | 2025-09-25 00:10:50.554126 | TASK [Install selinux into virtualenv] 2025-09-25 00:10:53.191924 | controller | Collecting selinux-please-lie-to-me 2025-09-25 00:10:53.287512 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-25 00:10:53.822031 | controller | Collecting setuptools<50.0.0 2025-09-25 00:10:53.836965 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-25 00:10:53.979215 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.0 MB/s eta 0:00:00 2025-09-25 00:10:54.132926 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-25 00:10:54.133368 | controller | Attempting uninstall: setuptools 2025-09-25 00:10:54.138414 | controller | Found existing installation: setuptools 62.6.0 2025-09-25 00:10:54.252276 | controller | Uninstalling setuptools-62.6.0: 2025-09-25 00:10:54.267278 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-25 00:10:55.016570 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-25 00:10:55.230377 | controller | 2025-09-25 00:10:55.452129 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-25 00:10:55.452183 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-25 00:10:55.811717 | controller | ok: Runtime: 0:00:04.419722 2025-09-25 00:10:55.824906 | 2025-09-25 00:10:55.825100 | TASK [Install pytest-forked into virtualenv] 2025-09-25 00:10:57.051708 | controller | Collecting pytest-forked 2025-09-25 00:10:57.143715 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-25 00:10:57.201550 | controller | Collecting py 2025-09-25 00:10:57.215732 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-25 00:10:57.252220 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-09-25 00:10:57.427783 | controller | Collecting pytest>=3.10 2025-09-25 00:10:57.441746 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-25 00:10:57.510178 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.5 MB/s eta 0:00:00 2025-09-25 00:10:57.586479 | controller | Collecting iniconfig>=1 2025-09-25 00:10:57.600647 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-25 00:10:57.667939 | controller | Collecting packaging>=20 2025-09-25 00:10:57.681853 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-25 00:10:57.695180 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.0 MB/s eta 0:00:00 2025-09-25 00:10:57.740721 | controller | Collecting pluggy<2,>=1.5 2025-09-25 00:10:57.756289 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-25 00:10:57.831013 | controller | Collecting pygments>=2.7.2 2025-09-25 00:10:57.844750 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-25 00:10:57.987265 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 8.8 MB/s eta 0:00:00 2025-09-25 00:10:58.117276 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-25 00:11:00.368604 | 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-09-25 00:11:00.385056 | controller | 2025-09-25 00:11:00.579400 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-25 00:11:00.579454 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-25 00:11:01.013346 | controller | ok: Runtime: 0:00:04.268535 2025-09-25 00:11:01.029137 | 2025-09-25 00:11:01.029425 | TASK [Update pip] 2025-09-25 00:11:02.616282 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-25 00:11:03.232035 | controller | Collecting pip 2025-09-25 00:11:03.378813 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-25 00:11:03.492738 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 16.0 MB/s eta 0:00:00 2025-09-25 00:11:03.633600 | controller | Installing collected packages: pip 2025-09-25 00:11:03.633955 | controller | Attempting uninstall: pip 2025-09-25 00:11:03.638534 | controller | Found existing installation: pip 22.2.2 2025-09-25 00:11:03.907403 | controller | Uninstalling pip-22.2.2: 2025-09-25 00:11:03.937200 | controller | Successfully uninstalled pip-22.2.2 2025-09-25 00:11:05.749009 | controller | Successfully installed pip-25.2 2025-09-25 00:11:06.202403 | controller | ok: Runtime: 0:00:04.230409 2025-09-25 00:11:06.217295 | 2025-09-25 00:11:06.217763 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-25 00:11:06.752337 | controller | changed 2025-09-25 00:11:06.757709 | 2025-09-25 00:11:06.757786 | TASK [Install ansible into virtualenv] 2025-09-25 00:11:07.976306 | controller | Processing ./src/github.com/ansible/ansible 2025-09-25 00:11:07.983878 | controller | Installing build dependencies: started 2025-09-25 00:11:09.979056 | controller | Installing build dependencies: finished with status 'done' 2025-09-25 00:11:11.541156 | controller | Getting requirements to build wheel: started 2025-09-25 00:11:11.541221 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-25 00:11:11.541480 | controller | Preparing metadata (pyproject.toml): started 2025-09-25 00:11:12.467157 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-25 00:11:12.472145 | 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-09-25 00:11:12.477074 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-25 00:11:12.906925 | controller | ERROR 2025-09-25 00:11:12.907372 | controller | { 2025-09-25 00:11:12.907448 | controller | "delta": "0:00:05.387826", 2025-09-25 00:11:12.907493 | controller | "end": "2025-09-25 00:11:12.629683", 2025-09-25 00:11:12.907537 | controller | "msg": "non-zero return code", 2025-09-25 00:11:12.907595 | controller | "rc": 1, 2025-09-25 00:11:12.907635 | controller | "start": "2025-09-25 00:11:07.241857" 2025-09-25 00:11:12.907672 | controller | } failure 2025-09-25 00:11:12.912312 | 2025-09-25 00:11:12.912515 | PLAY RECAP 2025-09-25 00:11:12.912624 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-25 00:11:12.912685 | 2025-09-25 00:11:13.080759 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-25 00:11:13.081704 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-25 00:11:13.688497 | 2025-09-25 00:11:13.688641 | PLAY [all] 2025-09-25 00:11:13.710383 | 2025-09-25 00:11:13.710521 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-25 00:11:14.458934 | controller | changed: non-zero return code 2025-09-25 00:11:14.466213 | 2025-09-25 00:11:14.466330 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-25 00:11:14.481923 | controller | skipping: Conditional result was False 2025-09-25 00:11:14.489904 | 2025-09-25 00:11:14.490011 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-25 00:11:14.524708 | 2025-09-25 00:11:14.524908 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-25 00:11:14.558290 | 2025-09-25 00:11:14.558512 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-25 00:11:14.584606 | controller | skipping: Conditional result was False 2025-09-25 00:11:14.593967 | 2025-09-25 00:11:14.594106 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-25 00:11:14.620843 | 2025-09-25 00:11:14.621067 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-25 00:11:14.636251 | controller | skipping: Conditional result was False 2025-09-25 00:11:14.645593 | 2025-09-25 00:11:14.645695 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-25 00:11:14.660696 | controller | skipping: Conditional result was False 2025-09-25 00:11:14.669899 | 2025-09-25 00:11:14.669995 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-25 00:11:14.684773 | controller | skipping: Conditional result was False 2025-09-25 00:11:14.722637 | 2025-09-25 00:11:14.722752 | PLAY RECAP 2025-09-25 00:11:14.722796 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-25 00:11:14.722817 | 2025-09-25 00:11:14.825895 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-25 00:11:14.826892 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-25 00:11:15.375544 | 2025-09-25 00:11:15.375778 | PLAY [all:!appliance*] 2025-09-25 00:11:15.399704 | 2025-09-25 00:11:15.400169 | TASK [unregister the node] 2025-09-25 00:11:15.540920 | controller | skipping: Conditional result was False 2025-09-25 00:11:15.552577 | 2025-09-25 00:11:15.552765 | TASK [include_role : fetch-output] 2025-09-25 00:11:15.590726 | controller | ok 2025-09-25 00:11:15.623490 | 2025-09-25 00:11:15.623653 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-25 00:11:15.670499 | controller | skipping: Conditional result was False 2025-09-25 00:11:15.683764 | 2025-09-25 00:11:15.683932 | TASK [fetch-output : Set log path for single node] 2025-09-25 00:11:15.727244 | controller | ok 2025-09-25 00:11:15.734490 | 2025-09-25 00:11:15.734571 | LOOP [fetch-output : Ensure local output dirs] 2025-09-25 00:11:16.144227 | controller -> localhost | ok: "/var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/logs" 2025-09-25 00:11:16.389257 | controller -> localhost | changed: "/var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/artifacts" 2025-09-25 00:11:16.644457 | controller -> localhost | changed: "/var/lib/zuul/builds/c91ec58183774daf8d5cddd964621bb3/work/docs" 2025-09-25 00:11:16.666133 | 2025-09-25 00:11:16.666352 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-25 00:11:17.890843 | controller | changed: 2025-09-25 00:11:17.891250 | controller | .d..t...... ./ 2025-09-25 00:11:17.891336 | controller | cd+++++++++ controller/ 2025-09-25 00:11:17.891439 | controller | changed: All items complete 2025-09-25 00:11:17.891539 | 2025-09-25 00:11:18.985747 | controller | changed: .d..t...... ./ 2025-09-25 00:11:20.086488 | controller | changed: .d..t...... ./ 2025-09-25 00:11:20.111843 | 2025-09-25 00:11:20.112049 | TASK [include_role : fetch-output-openshift] 2025-09-25 00:11:20.137805 | controller | skipping: Conditional result was False 2025-09-25 00:11:20.148118 | 2025-09-25 00:11:20.148273 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-25 00:11:20.191994 | controller | skipping: Conditional result was False 2025-09-25 00:11:20.205183 | controller | skipping: Conditional result was False 2025-09-25 00:11:20.257481 | 2025-09-25 00:11:20.257622 | PLAY [localhost] 2025-09-25 00:11:20.278093 | 2025-09-25 00:11:20.278243 | TASK [Run Zuul manifest role] 2025-09-25 00:11:20.299042 | localhost | ok 2025-09-25 00:11:20.319397 | 2025-09-25 00:11:20.319548 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-25 00:11:20.745784 | localhost | changed 2025-09-25 00:11:20.755901 | 2025-09-25 00:11:20.756102 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-25 00:11:20.802907 | localhost | ok 2025-09-25 00:11:20.821220 | 2025-09-25 00:11:20.821393 | TASK [Set zuul-log-path fact] 2025-09-25 00:11:20.848548 | localhost | ok 2025-09-25 00:11:20.872903 | 2025-09-25 00:11:20.873064 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-25 00:11:20.914766 | localhost | ok 2025-09-25 00:11:20.927759 | 2025-09-25 00:11:20.927868 | LOOP [Run upload-logs-swift role] 2025-09-25 00:11:20.975764 | localhost | Output suppressed because no_log was given 2025-09-25 00:11:21.013245 | 2025-09-25 00:11:21.013385 | TASK [Set zuul-log-path fact] 2025-09-25 00:11:21.048904 | localhost | skipping: Conditional result was False 2025-09-25 00:11:21.057724 | 2025-09-25 00:11:21.057849 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-25 00:11:21.510340 | localhost -> localhost | ok: Runtime: 0:00:00.008683 2025-09-25 00:11:21.515889 | 2025-09-25 00:11:21.515967 | TASK [upload-logs-swift : Upload logs to swift]