2025-12-25 00:14:22.902773 | Job console starting... 2025-12-25 00:14:22.912659 | Updating repositories 2025-12-25 00:14:23.077152 | Preparing job workspace 2025-12-25 00:14:26.853927 | Running Ansible setup... 2025-12-25 00:14:31.806245 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:14:32.459273 | 2025-12-25 00:14:32.459419 | PLAY [localhost] 2025-12-25 00:14:32.468965 | 2025-12-25 00:14:32.469084 | TASK [Gathering Facts] 2025-12-25 00:14:33.594832 | localhost | ok 2025-12-25 00:14:33.611227 | 2025-12-25 00:14:33.611333 | TASK [Setup log path fact] 2025-12-25 00:14:33.632249 | localhost | ok 2025-12-25 00:14:33.645061 | 2025-12-25 00:14:33.645141 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:14:33.673738 | localhost | ok 2025-12-25 00:14:33.681579 | 2025-12-25 00:14:33.681674 | TASK [emit-job-header : Print job information] 2025-12-25 00:14:33.710186 | # Job Information 2025-12-25 00:14:33.710355 | Ansible Version: 2.15.12 2025-12-25 00:14:33.710387 | Job: ansible-test-sanity-docker-devel 2025-12-25 00:14:33.710408 | Pipeline: periodic 2025-12-25 00:14:33.710425 | Executor: ze01.softwarefactory-project.io 2025-12-25 00:14:33.710443 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-25 00:14:33.710463 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/9f0/ansible/9f0e3eff25584a2a84947e0b968d942a/ 2025-12-25 00:14:33.710482 | Event ID: 9bcd164eed0a4284892079c0f800abca 2025-12-25 00:14:33.715309 | 2025-12-25 00:14:33.715389 | LOOP [emit-job-header : Print node information] 2025-12-25 00:14:33.816951 | localhost | ok: 2025-12-25 00:14:33.817144 | localhost | # Node Information 2025-12-25 00:14:33.817175 | localhost | Inventory Hostname: controller 2025-12-25 00:14:33.817195 | localhost | Hostname: np0005570309 2025-12-25 00:14:33.817215 | localhost | Username: zuul 2025-12-25 00:14:33.817237 | localhost | Distro: Fedora 37 2025-12-25 00:14:33.817255 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-25 00:14:33.817272 | localhost | Region: ca-ymq-1 2025-12-25 00:14:33.817288 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-25 00:14:33.817305 | localhost | Product Name: OpenStack Nova 2025-12-25 00:14:33.817321 | localhost | Interface IP: 162.253.55.204 2025-12-25 00:14:33.828223 | 2025-12-25 00:14:33.828292 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-25 00:14:34.300431 | localhost -> localhost | changed 2025-12-25 00:14:34.306693 | 2025-12-25 00:14:34.306802 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-25 00:14:35.290325 | localhost -> localhost | changed 2025-12-25 00:14:35.318227 | 2025-12-25 00:14:35.318349 | PLAY [all:!appliance*] 2025-12-25 00:14:35.337196 | 2025-12-25 00:14:35.337350 | TASK [include_role : start-zuul-console] 2025-12-25 00:14:35.360789 | controller | ok 2025-12-25 00:14:35.376529 | 2025-12-25 00:14:35.376660 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-25 00:14:35.775705 | controller | ok 2025-12-25 00:14:35.800722 | 2025-12-25 00:14:35.800970 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-25 00:14:56.025005 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-25 00:14:56.040188 | 2025-12-25 00:14:56.040342 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-25 00:14:56.580424 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.590456 | 2025-12-25 00:14:56.590608 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-25 00:14:56.616010 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.626735 | 2025-12-25 00:14:56.626979 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-25 00:14:56.663341 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.673697 | 2025-12-25 00:14:56.673828 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-25 00:14:56.699082 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.708702 | 2025-12-25 00:14:56.708852 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-25 00:14:56.734752 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.744157 | 2025-12-25 00:14:56.744306 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-25 00:14:56.770656 | controller | skipping: Conditional result was False 2025-12-25 00:14:56.785777 | 2025-12-25 00:14:56.785913 | TASK [Disable Fedora Modular] 2025-12-25 00:14:57.153832 | controller | changed 2025-12-25 00:14:57.161140 | 2025-12-25 00:14:57.161287 | TASK [Enable EPEL] 2025-12-25 00:14:57.185960 | controller | skipping: Conditional result was False 2025-12-25 00:14:57.193662 | 2025-12-25 00:14:57.193761 | TASK [Register the RHEL node] 2025-12-25 00:14:57.747902 | 2025-12-25 00:14:57.748279 | TASK [Show the subscription-manager status] 2025-12-25 00:14:58.311848 | controller | skipping: Conditional result was False 2025-12-25 00:14:58.327731 | 2025-12-25 00:14:58.327897 | TASK [Enable EPEL on RHEL] 2025-12-25 00:14:58.395471 | controller | skipping: Conditional result was False 2025-12-25 00:14:58.404261 | 2025-12-25 00:14:58.404349 | TASK [Install git and tox] 2025-12-25 00:16:25.444873 | controller | changed 2025-12-25 00:16:25.461200 | 2025-12-25 00:16:25.461384 | TASK [include_role : prepare-workspace] 2025-12-25 00:16:25.500378 | controller | ok 2025-12-25 00:16:25.538363 | 2025-12-25 00:16:25.538538 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-25 00:16:25.764370 | controller | ok 2025-12-25 00:16:25.773100 | 2025-12-25 00:16:25.773208 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-25 00:16:38.033205 | controller | Output suppressed because no_log was given 2025-12-25 00:16:38.053356 | 2025-12-25 00:16:38.053477 | TASK [include_role : prepare-workspace-openshift] 2025-12-25 00:16:38.079431 | controller | skipping: Conditional result was False 2025-12-25 00:16:38.110789 | 2025-12-25 00:16:38.110893 | PLAY [all:!appliance] 2025-12-25 00:16:38.135337 | 2025-12-25 00:16:38.135491 | TASK [Run add-build-sshkey role (RSA)] 2025-12-25 00:16:38.158984 | controller | ok 2025-12-25 00:16:38.179507 | 2025-12-25 00:16:38.179691 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:16:38.462123 | controller -> localhost | ok 2025-12-25 00:16:38.469583 | 2025-12-25 00:16:38.469714 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:16:38.495011 | controller | ok 2025-12-25 00:16:38.516488 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:16:38.527355 | 2025-12-25 00:16:38.527522 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:16:39.052395 | controller -> localhost | Generating public/private rsa key pair. 2025-12-25 00:16:39.052753 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_rsa. 2025-12-25 00:16:39.052786 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_rsa.pub. 2025-12-25 00:16:39.052808 | controller -> localhost | The key fingerprint is: 2025-12-25 00:16:39.052828 | controller -> localhost | SHA256:rJqCz1IYdtPkfykDpxnb4PA3/tjp5YToQsZw0qA4Ri8 zuul-build-sshkey 2025-12-25 00:16:39.052847 | controller -> localhost | The key's randomart image is: 2025-12-25 00:16:39.052866 | controller -> localhost | +---[RSA 2048]----+ 2025-12-25 00:16:39.052885 | controller -> localhost | | | 2025-12-25 00:16:39.052904 | controller -> localhost | | . . . | 2025-12-25 00:16:39.052922 | controller -> localhost | |o o * | 2025-12-25 00:16:39.052939 | controller -> localhost | |+E B O o | 2025-12-25 00:16:39.052957 | controller -> localhost | |o+o X @ S . | 2025-12-25 00:16:39.052986 | controller -> localhost | |. . X O.o. | 2025-12-25 00:16:39.053039 | controller -> localhost | | o o +.=. o | 2025-12-25 00:16:39.053067 | controller -> localhost | |o.. +..o = | 2025-12-25 00:16:39.053087 | controller -> localhost | | oo.o .oo= . | 2025-12-25 00:16:39.053108 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:16:39.053163 | controller -> localhost | ok: Runtime: 0:00:00.051487 2025-12-25 00:16:39.060878 | 2025-12-25 00:16:39.060965 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:16:39.097852 | controller | ok 2025-12-25 00:16:39.108794 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:16:39.118078 | 2025-12-25 00:16:39.118143 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:16:39.144940 | controller | skipping: Conditional result was False 2025-12-25 00:16:39.153522 | 2025-12-25 00:16:39.153614 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:16:39.651225 | controller | changed 2025-12-25 00:16:39.661124 | 2025-12-25 00:16:39.661279 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:16:39.888864 | controller | ok 2025-12-25 00:16:39.895543 | 2025-12-25 00:16:39.895658 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:16:40.541355 | controller | changed 2025-12-25 00:16:40.558325 | 2025-12-25 00:16:40.558605 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:16:41.206473 | controller | changed 2025-12-25 00:16:41.215351 | 2025-12-25 00:16:41.215440 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:16:41.234075 | controller | skipping: Conditional result was False 2025-12-25 00:16:41.280829 | 2025-12-25 00:16:41.281136 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:16:41.668448 | controller -> localhost | changed 2025-12-25 00:16:41.695401 | 2025-12-25 00:16:41.695658 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:16:42.044311 | controller -> localhost | Identity added: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_rsa (zuul-build-sshkey) 2025-12-25 00:16:42.044616 | controller -> localhost | ok: Runtime: 0:00:00.015963 2025-12-25 00:16:42.057657 | 2025-12-25 00:16:42.057769 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:16:42.386752 | controller | ok 2025-12-25 00:16:42.404718 | 2025-12-25 00:16:42.404919 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:16:42.443632 | controller | skipping: Conditional result was False 2025-12-25 00:16:42.471520 | 2025-12-25 00:16:42.471891 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-25 00:16:42.508797 | controller | ok 2025-12-25 00:16:42.538076 | 2025-12-25 00:16:42.538284 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:16:42.814751 | controller -> localhost | ok 2025-12-25 00:16:42.823334 | 2025-12-25 00:16:42.823490 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:16:42.856463 | controller | ok 2025-12-25 00:16:42.876727 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:16:42.888266 | 2025-12-25 00:16:42.888434 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:16:43.232882 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-25 00:16:43.233185 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_ecdsa. 2025-12-25 00:16:43.233217 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_ecdsa.pub. 2025-12-25 00:16:43.233250 | controller -> localhost | The key fingerprint is: 2025-12-25 00:16:43.233272 | controller -> localhost | SHA256:mcX1UsW6q7JQP4klLBEMTopq0JvQwlWAvo+8DLnXDKk zuul-build-sshkey 2025-12-25 00:16:43.233291 | controller -> localhost | The key's randomart image is: 2025-12-25 00:16:43.233310 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-25 00:16:43.233328 | controller -> localhost | | .oo.oo. . .o.| 2025-12-25 00:16:43.233345 | controller -> localhost | |.+.. + .o . o .| 2025-12-25 00:16:43.233362 | controller -> localhost | |=.+ . . . o . .. | 2025-12-25 00:16:43.233379 | controller -> localhost | |.= o * .. | 2025-12-25 00:16:43.233396 | controller -> localhost | |..+. S + . . | 2025-12-25 00:16:43.233413 | controller -> localhost | |.oo o = .. | 2025-12-25 00:16:43.233430 | controller -> localhost | |+.o+ . . + . | 2025-12-25 00:16:43.233447 | controller -> localhost | |E+..o .. .. | 2025-12-25 00:16:43.233464 | controller -> localhost | |.+. .o.. | 2025-12-25 00:16:43.233481 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:16:43.233534 | controller -> localhost | ok: Runtime: 0:00:00.010178 2025-12-25 00:16:43.243150 | 2025-12-25 00:16:43.243274 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:16:43.277003 | controller | ok 2025-12-25 00:16:43.287294 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:16:43.299053 | 2025-12-25 00:16:43.299170 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:16:43.337993 | controller | skipping: Conditional result was False 2025-12-25 00:16:43.346593 | 2025-12-25 00:16:43.346723 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:16:43.609446 | controller | changed 2025-12-25 00:16:43.621653 | 2025-12-25 00:16:43.621795 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:16:43.888176 | controller | ok 2025-12-25 00:16:43.904136 | 2025-12-25 00:16:43.904313 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:16:44.593280 | controller | changed 2025-12-25 00:16:44.605622 | 2025-12-25 00:16:44.605721 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:16:45.236716 | controller | changed 2025-12-25 00:16:45.250360 | 2025-12-25 00:16:45.250639 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:16:45.278493 | controller | skipping: Conditional result was False 2025-12-25 00:16:45.291945 | 2025-12-25 00:16:45.292202 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:16:45.545632 | controller -> localhost | changed 2025-12-25 00:16:45.559922 | 2025-12-25 00:16:45.560078 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:16:45.914858 | controller -> localhost | Identity added: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/9f0e3eff25584a2a84947e0b968d942a_id_ecdsa (zuul-build-sshkey) 2025-12-25 00:16:45.915200 | controller -> localhost | ok: Runtime: 0:00:00.015625 2025-12-25 00:16:45.925308 | 2025-12-25 00:16:45.925500 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:16:46.160588 | controller | ok 2025-12-25 00:16:46.172812 | 2025-12-25 00:16:46.173057 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:16:46.224638 | controller | skipping: Conditional result was False 2025-12-25 00:16:46.241993 | 2025-12-25 00:16:46.242209 | TASK [include_role : remove-zuul-sshkey] 2025-12-25 00:16:46.270064 | controller | skipping: Conditional result was False 2025-12-25 00:16:46.280532 | 2025-12-25 00:16:46.280684 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-25 00:16:46.538897 | controller | ok: "logs" 2025-12-25 00:16:46.539291 | controller | ok: All items complete 2025-12-25 00:16:46.539328 | 2025-12-25 00:16:46.741581 | controller | ok: "artifacts" 2025-12-25 00:16:46.935872 | controller | ok: "docs" 2025-12-25 00:16:46.955302 | 2025-12-25 00:16:46.955509 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-25 00:16:47.211485 | controller | changed: "logs" 2025-12-25 00:16:47.412290 | controller | changed: "artifacts" 2025-12-25 00:16:47.590113 | controller | changed: "docs" 2025-12-25 00:16:47.634615 | 2025-12-25 00:16:47.634789 | PLAY RECAP 2025-12-25 00:16:47.634859 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-25 00:16:47.634894 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-25 00:16:47.634920 | 2025-12-25 00:16:47.877678 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:16:47.878677 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:16:48.546601 | 2025-12-25 00:16:48.546877 | PLAY [all] 2025-12-25 00:16:48.592067 | 2025-12-25 00:16:48.592298 | TASK [Install binary dependencies] 2025-12-25 00:16:48.657453 | controller | ok 2025-12-25 00:16:48.679297 | 2025-12-25 00:16:48.679527 | TASK [bindep : Include find tasks] 2025-12-25 00:16:48.712156 | controller | ok 2025-12-25 00:16:48.721308 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-25 00:16:48.728073 | 2025-12-25 00:16:48.728170 | TASK [bindep : Look for bindep.txt] 2025-12-25 00:16:49.098038 | controller | ok 2025-12-25 00:16:49.114186 | 2025-12-25 00:16:49.114442 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:16:49.144225 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.161810 | 2025-12-25 00:16:49.162091 | TASK [bindep : Look for other-requirements.txt] 2025-12-25 00:16:49.385278 | controller | ok 2025-12-25 00:16:49.394833 | 2025-12-25 00:16:49.394961 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:16:49.431923 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.439974 | 2025-12-25 00:16:49.440134 | TASK [bindep : Look for bindep fallback file] 2025-12-25 00:16:49.477361 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.485284 | 2025-12-25 00:16:49.485369 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:16:49.510836 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.519423 | 2025-12-25 00:16:49.519506 | TASK [bindep : Include bindep tasks] 2025-12-25 00:16:49.544563 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.552199 | 2025-12-25 00:16:49.552275 | TASK [bindep : Include install tasks] 2025-12-25 00:16:49.577168 | controller | skipping: Conditional result was False 2025-12-25 00:16:49.587687 | 2025-12-25 00:16:49.587850 | LOOP [bindep : Include package tasks] 2025-12-25 00:16:49.678390 | 2025-12-25 00:16:49.678689 | TASK [Run test-setup role] 2025-12-25 00:16:49.706924 | controller | ok 2025-12-25 00:16:49.731145 | 2025-12-25 00:16:49.731807 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-25 00:16:49.963036 | controller | ok 2025-12-25 00:16:49.973492 | 2025-12-25 00:16:49.973683 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-25 00:16:50.522587 | controller | skipping: Conditional result was False 2025-12-25 00:16:50.560976 | 2025-12-25 00:16:50.561182 | PLAY RECAP 2025-12-25 00:16:50.561250 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:16:50.561281 | 2025-12-25 00:16:50.784427 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:16:50.785631 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:16:51.471330 | 2025-12-25 00:16:51.471799 | PLAY [controller] 2025-12-25 00:16:51.494398 | 2025-12-25 00:16:51.494526 | TASK [Create the /root directory] 2025-12-25 00:16:51.975108 | controller | ok 2025-12-25 00:16:51.994919 | 2025-12-25 00:16:51.995162 | TASK [Install glibc-langpack-en] 2025-12-25 00:16:56.243619 | controller | ok: Nothing to do 2025-12-25 00:16:56.251202 | 2025-12-25 00:16:56.251351 | TASK [Ensure controller directory exists] 2025-12-25 00:16:56.448782 | controller | changed 2025-12-25 00:16:56.454979 | 2025-12-25 00:16:56.455070 | TASK [Install container runtime] 2025-12-25 00:16:56.505972 | controller | ok 2025-12-25 00:16:56.567195 | 2025-12-25 00:16:56.567358 | LOOP [ensure-podman : Find distribution installation] 2025-12-25 00:16:56.612778 | controller | ok: "/var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-25 00:16:56.627949 | controller | included: /var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-25 00:16:56.646961 | 2025-12-25 00:16:56.647231 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-25 00:18:01.747531 | controller | changed 2025-12-25 00:18:01.763579 | 2025-12-25 00:18:01.763791 | TASK [ensure-podman : Fetch podman version] 2025-12-25 00:18:02.322649 | controller | Client: Podman Engine 2025-12-25 00:18:02.354689 | controller | Version: 4.6.2 2025-12-25 00:18:02.354741 | controller | API Version: 4.6.2 2025-12-25 00:18:02.354754 | controller | Go Version: go1.19.12 2025-12-25 00:18:02.354800 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:18:02.354813 | controller | OS/Arch: linux/amd64 2025-12-25 00:18:02.822768 | controller | ok: Runtime: 0:00:00.194147 2025-12-25 00:18:02.840625 | 2025-12-25 00:18:02.840904 | TASK [ensure-podman : Print podman version installed] 2025-12-25 00:18:02.887285 | Podman version: Client: Podman Engine 2025-12-25 00:18:02.887734 | Version: 4.6.2 2025-12-25 00:18:02.887832 | API Version: 4.6.2 2025-12-25 00:18:02.887906 | Go Version: go1.19.12 2025-12-25 00:18:02.887978 | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:18:02.888158 | OS/Arch: linux/amd64 2025-12-25 00:18:02.905481 | 2025-12-25 00:18:02.905695 | TASK [ensure-podman : Validate podman engine] 2025-12-25 00:18:03.451726 | controller | skipping: Conditional result was False 2025-12-25 00:18:03.461316 | 2025-12-25 00:18:03.461724 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-25 00:18:03.487949 | controller | skipping: Conditional result was False 2025-12-25 00:18:03.505511 | 2025-12-25 00:18:03.505659 | TASK [Ensure python3.8 is present] 2025-12-25 00:18:03.532409 | controller | skipping: Conditional result was False 2025-12-25 00:18:03.542145 | 2025-12-25 00:18:03.542313 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-25 00:18:03.567491 | controller | ok 2025-12-25 00:18:03.592849 | 2025-12-25 00:18:03.593052 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-25 00:18:05.128397 | controller | ok: Nothing to do 2025-12-25 00:18:05.136092 | 2025-12-25 00:18:05.136180 | TASK [our-ensure-python : Also install python3-devel] 2025-12-25 00:18:14.234726 | controller | changed 2025-12-25 00:18:14.259741 | 2025-12-25 00:18:14.259895 | TASK [Run ensure-virtualenv role] 2025-12-25 00:18:14.287316 | controller | ok 2025-12-25 00:18:14.316341 | 2025-12-25 00:18:14.316481 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-25 00:18:14.553456 | controller | /usr/bin/virtualenv 2025-12-25 00:18:14.883254 | controller | ok: Runtime: 0:00:00.005131 2025-12-25 00:18:14.895187 | 2025-12-25 00:18:14.895355 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-25 00:18:14.928696 | controller | skipping: Conditional result was False 2025-12-25 00:18:14.929205 | controller | ok: All items complete 2025-12-25 00:18:14.929285 | 2025-12-25 00:18:14.945762 | 2025-12-25 00:18:14.945911 | TASK [Find the full path of the Python interpreter] 2025-12-25 00:18:15.170628 | controller | /usr/bin/python3 2025-12-25 00:18:15.478269 | controller | ok 2025-12-25 00:18:15.488710 | 2025-12-25 00:18:15.488851 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-25 00:18:16.540627 | controller | created virtual environment CPython3.11.0.final.0-64 in 539ms 2025-12-25 00:18:16.562884 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-25 00:18:16.562899 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-12-25 00:18:16.562915 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-25 00:18:16.562927 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-25 00:18:17.045778 | controller | changed 2025-12-25 00:18:17.056943 | 2025-12-25 00:18:17.057150 | TASK [Set selinux package] 2025-12-25 00:18:17.099952 | controller | ok 2025-12-25 00:18:17.112784 | 2025-12-25 00:18:17.112932 | TASK [Set selinux package (Fedora)] 2025-12-25 00:18:17.169319 | controller | ok 2025-12-25 00:18:17.176753 | 2025-12-25 00:18:17.176848 | TASK [Install selinux into virtualenv] 2025-12-25 00:18:42.716109 | controller | Collecting selinux-please-lie-to-me 2025-12-25 00:19:18.980027 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-25 00:19:19.285336 | controller | Collecting setuptools<50.0.0 2025-12-25 00:19:19.290778 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-25 00:19:19.336118 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.1 MB/s eta 0:00:00 2025-12-25 00:19:19.414040 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-25 00:19:19.414197 | controller | Attempting uninstall: setuptools 2025-12-25 00:19:19.416621 | controller | Found existing installation: setuptools 62.6.0 2025-12-25 00:19:19.475501 | controller | Uninstalling setuptools-62.6.0: 2025-12-25 00:19:19.483917 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-25 00:19:19.845823 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-25 00:19:36.107105 | controller | 2025-12-25 00:19:36.192564 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:19:36.192730 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:19:36.271494 | controller | ok: Runtime: 0:01:18.784477 2025-12-25 00:19:36.280002 | 2025-12-25 00:19:36.280147 | TASK [Install pytest-forked into virtualenv] 2025-12-25 00:19:52.309063 | controller | Collecting pytest-forked 2025-12-25 00:20:04.546140 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-25 00:20:04.592883 | controller | Collecting py 2025-12-25 00:20:04.598114 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-25 00:20:04.611634 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 9.9 MB/s eta 0:00:00 2025-12-25 00:20:04.719115 | controller | Collecting pytest>=3.10 2025-12-25 00:20:04.724619 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-25 00:20:04.738905 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 34.2 MB/s eta 0:00:00 2025-12-25 00:20:04.773855 | controller | Collecting iniconfig>=1.0.1 2025-12-25 00:20:04.778170 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-25 00:20:04.824651 | controller | Collecting packaging>=22 2025-12-25 00:20:04.828397 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-25 00:20:04.835094 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 15.1 MB/s eta 0:00:00 2025-12-25 00:20:04.871015 | controller | Collecting pluggy<2,>=1.5 2025-12-25 00:20:04.874685 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-25 00:20:04.921061 | controller | Collecting pygments>=2.7.2 2025-12-25 00:20:04.924766 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-25 00:20:04.955069 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 49.0 MB/s eta 0:00:00 2025-12-25 00:20:05.026099 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-25 00:20:06.019460 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-25 00:20:06.028388 | controller | 2025-12-25 00:20:06.097736 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:20:06.097781 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:20:06.347346 | controller | ok: Runtime: 0:00:29.581521 2025-12-25 00:20:06.355996 | 2025-12-25 00:20:06.356131 | TASK [Update pip] 2025-12-25 00:20:06.869465 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-25 00:20:43.242614 | controller | Collecting pip 2025-12-25 00:21:07.368458 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-25 00:21:07.435613 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 29.0 MB/s eta 0:00:00 2025-12-25 00:21:07.497684 | controller | Installing collected packages: pip 2025-12-25 00:21:07.497927 | controller | Attempting uninstall: pip 2025-12-25 00:21:07.500149 | controller | Found existing installation: pip 22.2.2 2025-12-25 00:21:07.636758 | controller | Uninstalling pip-22.2.2: 2025-12-25 00:21:07.652073 | controller | Successfully uninstalled pip-22.2.2 2025-12-25 00:21:08.448120 | controller | Successfully installed pip-25.3 2025-12-25 00:21:08.933506 | controller | ok: Runtime: 0:01:01.971311 2025-12-25 00:21:08.942663 | 2025-12-25 00:21:08.942818 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-25 00:21:09.170148 | controller | changed 2025-12-25 00:21:09.180514 | 2025-12-25 00:21:09.180602 | TASK [Install ansible into virtualenv] 2025-12-25 00:21:09.799418 | controller | Processing ./src/github.com/ansible/ansible 2025-12-25 00:21:09.803360 | controller | Installing build dependencies: started 2025-12-25 00:22:10.863556 | controller | Installing build dependencies: still running... 2025-12-25 00:22:11.224199 | controller | Installing build dependencies: finished with status 'done' 2025-12-25 00:22:11.224949 | controller | Getting requirements to build wheel: started 2025-12-25 00:22:12.025856 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-25 00:22:12.026982 | controller | Preparing metadata (pyproject.toml): started 2025-12-25 00:22:12.510608 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-25 00:22:12.515743 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-12-25 00:22:12.520113 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-25 00:22:12.808398 | controller | ERROR 2025-12-25 00:22:12.808877 | controller | { 2025-12-25 00:22:12.808955 | controller | "delta": "0:01:03.108503", 2025-12-25 00:22:12.809102 | controller | "end": "2025-12-25 00:22:12.596745", 2025-12-25 00:22:12.809171 | controller | "msg": "non-zero return code", 2025-12-25 00:22:12.809213 | controller | "rc": 1, 2025-12-25 00:22:12.809252 | controller | "start": "2025-12-25 00:21:09.488242" 2025-12-25 00:22:12.809290 | controller | } failure 2025-12-25 00:22:12.812300 | 2025-12-25 00:22:12.812434 | PLAY RECAP 2025-12-25 00:22:12.812569 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-25 00:22:12.812650 | 2025-12-25 00:22:12.963855 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:22:12.964868 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:22:13.617825 | 2025-12-25 00:22:13.617956 | PLAY [all] 2025-12-25 00:22:13.641425 | 2025-12-25 00:22:13.641598 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-25 00:22:13.909561 | controller | changed: non-zero return code 2025-12-25 00:22:13.915763 | 2025-12-25 00:22:13.915839 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-25 00:22:13.940387 | controller | skipping: Conditional result was False 2025-12-25 00:22:13.946475 | 2025-12-25 00:22:13.946546 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-25 00:22:13.968274 | 2025-12-25 00:22:13.968403 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-25 00:22:13.998256 | 2025-12-25 00:22:13.998377 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-25 00:22:14.012746 | controller | skipping: Conditional result was False 2025-12-25 00:22:14.020949 | 2025-12-25 00:22:14.021039 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-25 00:22:14.054368 | 2025-12-25 00:22:14.054582 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-25 00:22:14.070787 | controller | skipping: Conditional result was False 2025-12-25 00:22:14.080211 | 2025-12-25 00:22:14.080324 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-25 00:22:14.096344 | controller | skipping: Conditional result was False 2025-12-25 00:22:14.106914 | 2025-12-25 00:22:14.107082 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-25 00:22:14.123566 | controller | skipping: Conditional result was False 2025-12-25 00:22:14.159662 | 2025-12-25 00:22:14.159785 | PLAY RECAP 2025-12-25 00:22:14.159829 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:22:14.159850 | 2025-12-25 00:22:14.271172 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:22:14.272050 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-25 00:22:14.911271 | 2025-12-25 00:22:14.911391 | PLAY [all:!appliance*] 2025-12-25 00:22:14.933085 | 2025-12-25 00:22:14.933172 | TASK [unregister the node] 2025-12-25 00:22:15.468191 | controller | skipping: Conditional result was False 2025-12-25 00:22:15.474945 | 2025-12-25 00:22:15.475063 | TASK [include_role : fetch-output] 2025-12-25 00:22:15.504984 | controller | ok 2025-12-25 00:22:15.525374 | 2025-12-25 00:22:15.525491 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-25 00:22:15.570633 | controller | skipping: Conditional result was False 2025-12-25 00:22:15.578849 | 2025-12-25 00:22:15.578962 | TASK [fetch-output : Set log path for single node] 2025-12-25 00:22:15.620805 | controller | ok 2025-12-25 00:22:15.627033 | 2025-12-25 00:22:15.627112 | LOOP [fetch-output : Ensure local output dirs] 2025-12-25 00:22:16.064485 | controller -> localhost | ok: "/var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/logs" 2025-12-25 00:22:16.286856 | controller -> localhost | changed: "/var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/artifacts" 2025-12-25 00:22:16.525241 | controller -> localhost | changed: "/var/lib/zuul/builds/9f0e3eff25584a2a84947e0b968d942a/work/docs" 2025-12-25 00:22:16.545346 | 2025-12-25 00:22:16.545511 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-25 00:22:17.282381 | controller | changed: 2025-12-25 00:22:17.282717 | controller | .d..t...... ./ 2025-12-25 00:22:17.282842 | controller | cd+++++++++ controller/ 2025-12-25 00:22:17.282921 | controller | changed: All items complete 2025-12-25 00:22:17.283007 | 2025-12-25 00:22:17.776103 | controller | changed: .d..t...... ./ 2025-12-25 00:22:18.266069 | controller | changed: .d..t...... ./ 2025-12-25 00:22:18.299320 | 2025-12-25 00:22:18.299514 | TASK [include_role : fetch-output-openshift] 2025-12-25 00:22:18.327651 | controller | skipping: Conditional result was False 2025-12-25 00:22:18.336625 | 2025-12-25 00:22:18.336729 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-25 00:22:18.363415 | controller | skipping: Conditional result was False 2025-12-25 00:22:18.373032 | controller | skipping: Conditional result was False 2025-12-25 00:22:18.407957 | 2025-12-25 00:22:18.408061 | PLAY [localhost] 2025-12-25 00:22:18.419930 | 2025-12-25 00:22:18.420051 | TASK [Run Zuul manifest role] 2025-12-25 00:22:18.438976 | localhost | ok 2025-12-25 00:22:18.452517 | 2025-12-25 00:22:18.452596 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-25 00:22:18.877889 | localhost | changed 2025-12-25 00:22:18.884571 | 2025-12-25 00:22:18.884665 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-25 00:22:18.921826 | localhost | ok 2025-12-25 00:22:18.940997 | 2025-12-25 00:22:18.941127 | TASK [Set zuul-log-path fact] 2025-12-25 00:22:18.962312 | localhost | ok 2025-12-25 00:22:18.983669 | 2025-12-25 00:22:18.983804 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:22:19.015762 | localhost | ok 2025-12-25 00:22:19.029469 | 2025-12-25 00:22:19.029552 | LOOP [Run upload-logs-swift role] 2025-12-25 00:22:19.065560 | localhost | Output suppressed because no_log was given 2025-12-25 00:22:19.091718 | 2025-12-25 00:22:19.091842 | TASK [Set zuul-log-path fact] 2025-12-25 00:22:19.127155 | localhost | skipping: Conditional result was False 2025-12-25 00:22:19.135094 | 2025-12-25 00:22:19.135205 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-25 00:22:19.573877 | localhost -> localhost | ok: Runtime: 0:00:00.009367 2025-12-25 00:22:19.621902 | 2025-12-25 00:22:19.622071 | TASK [upload-logs-swift : Upload logs to swift]