2025-10-09 00:12:23.474234 | Job console starting... 2025-10-09 00:12:23.489125 | Updating repositories 2025-10-09 00:12:23.634134 | Preparing job workspace 2025-10-09 00:12:27.693470 | Running Ansible setup... 2025-10-09 00:12:33.403016 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:12:34.037051 | 2025-10-09 00:12:34.037191 | PLAY [localhost] 2025-10-09 00:12:34.046032 | 2025-10-09 00:12:34.046148 | TASK [Gathering Facts] 2025-10-09 00:12:35.116020 | localhost | ok 2025-10-09 00:12:35.139354 | 2025-10-09 00:12:35.139564 | TASK [Setup log path fact] 2025-10-09 00:12:35.161354 | localhost | ok 2025-10-09 00:12:35.180384 | 2025-10-09 00:12:35.180521 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:12:35.213866 | localhost | ok 2025-10-09 00:12:35.229635 | 2025-10-09 00:12:35.229811 | TASK [emit-job-header : Print job information] 2025-10-09 00:12:35.263965 | # Job Information 2025-10-09 00:12:35.264213 | Ansible Version: 2.15.12 2025-10-09 00:12:35.264268 | Job: ansible-test-sanity-docker-devel 2025-10-09 00:12:35.264305 | Pipeline: periodic 2025-10-09 00:12:35.264339 | Executor: ze03.softwarefactory-project.io 2025-10-09 00:12:35.264372 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-09 00:12:35.264412 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/806/ansible/8067f109b9f84758a517da0531b28fc4/ 2025-10-09 00:12:35.264447 | Event ID: 7e5f5b9352a645a081c4b0c8a3c28952 2025-10-09 00:12:35.270335 | 2025-10-09 00:12:35.270420 | LOOP [emit-job-header : Print node information] 2025-10-09 00:12:35.375001 | localhost | ok: 2025-10-09 00:12:35.375219 | localhost | # Node Information 2025-10-09 00:12:35.375247 | localhost | Inventory Hostname: controller 2025-10-09 00:12:35.375267 | localhost | Hostname: ip-172-16-58-245 2025-10-09 00:12:35.375287 | localhost | Username: zuul-worker 2025-10-09 00:12:35.375307 | localhost | Distro: Fedora 37 2025-10-09 00:12:35.375325 | localhost | Provider: ansible-us-east-2 2025-10-09 00:12:35.375344 | localhost | Region: us-east-2 2025-10-09 00:12:35.375361 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-09 00:12:35.375378 | localhost | Product Name: t3.small 2025-10-09 00:12:35.375396 | localhost | Interface IP: 18.117.176.207 2025-10-09 00:12:35.388405 | 2025-10-09 00:12:35.388558 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-09 00:12:35.876085 | localhost -> localhost | changed 2025-10-09 00:12:35.888200 | 2025-10-09 00:12:35.888341 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-09 00:12:36.837647 | localhost -> localhost | changed 2025-10-09 00:12:36.869122 | 2025-10-09 00:12:36.869221 | PLAY [all:!appliance*] 2025-10-09 00:12:36.889375 | 2025-10-09 00:12:36.889525 | TASK [include_role : start-zuul-console] 2025-10-09 00:12:36.920191 | controller | ok 2025-10-09 00:12:36.939763 | 2025-10-09 00:12:36.939902 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-09 00:12:37.650322 | controller | ok 2025-10-09 00:12:37.661406 | 2025-10-09 00:12:37.661531 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-09 00:12:39.308685 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-09 00:12:39.324391 | 2025-10-09 00:12:39.324557 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-09 00:12:39.473156 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.479971 | 2025-10-09 00:12:39.480045 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-09 00:12:39.514843 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.521142 | 2025-10-09 00:12:39.521211 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-09 00:12:39.545297 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.552427 | 2025-10-09 00:12:39.552507 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-09 00:12:39.576490 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.582491 | 2025-10-09 00:12:39.582566 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-09 00:12:39.606492 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.612565 | 2025-10-09 00:12:39.612638 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-09 00:12:39.636478 | controller | skipping: Conditional result was False 2025-10-09 00:12:39.648169 | 2025-10-09 00:12:39.648241 | TASK [Disable Fedora Modular] 2025-10-09 00:12:40.392301 | controller | changed 2025-10-09 00:12:40.401913 | 2025-10-09 00:12:40.401991 | TASK [Enable EPEL] 2025-10-09 00:12:40.419547 | controller | skipping: Conditional result was False 2025-10-09 00:12:40.426244 | 2025-10-09 00:12:40.426318 | TASK [Register the RHEL node] 2025-10-09 00:12:40.568024 | 2025-10-09 00:12:40.568174 | TASK [Show the subscription-manager status] 2025-10-09 00:12:40.738532 | controller | skipping: Conditional result was False 2025-10-09 00:12:40.752058 | 2025-10-09 00:12:40.752204 | TASK [Enable EPEL on RHEL] 2025-10-09 00:12:40.930524 | controller | skipping: Conditional result was False 2025-10-09 00:12:40.949007 | 2025-10-09 00:12:40.949196 | TASK [Install git and tox] 2025-10-09 00:14:15.765981 | controller | changed 2025-10-09 00:14:15.771936 | 2025-10-09 00:14:15.771994 | TASK [include_role : prepare-workspace] 2025-10-09 00:14:15.809428 | controller | ok 2025-10-09 00:14:15.844878 | 2025-10-09 00:14:15.845003 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-09 00:14:16.396384 | controller | ok 2025-10-09 00:14:16.404548 | 2025-10-09 00:14:16.404676 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-09 00:14:28.978122 | controller | Output suppressed because no_log was given 2025-10-09 00:14:28.994497 | 2025-10-09 00:14:28.994622 | TASK [include_role : prepare-workspace-openshift] 2025-10-09 00:14:29.011940 | controller | skipping: Conditional result was False 2025-10-09 00:14:29.040654 | 2025-10-09 00:14:29.040776 | PLAY [all:!appliance] 2025-10-09 00:14:29.057885 | 2025-10-09 00:14:29.058006 | TASK [Run add-build-sshkey role (RSA)] 2025-10-09 00:14:29.078850 | controller | ok 2025-10-09 00:14:29.133562 | 2025-10-09 00:14:29.133744 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:14:29.416128 | controller -> localhost | ok 2025-10-09 00:14:29.422907 | 2025-10-09 00:14:29.423011 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:14:29.452863 | controller | ok 2025-10-09 00:14:29.468786 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:14:29.474707 | 2025-10-09 00:14:29.474794 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:14:30.061935 | controller -> localhost | Generating public/private rsa key pair. 2025-10-09 00:14:30.062144 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_rsa. 2025-10-09 00:14:30.062175 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_rsa.pub. 2025-10-09 00:14:30.062197 | controller -> localhost | The key fingerprint is: 2025-10-09 00:14:30.062217 | controller -> localhost | SHA256:IXlymuHv9GKV8A8xePHNyOzS8aC+dk7dH7CcZiQc2F8 zuul-build-sshkey 2025-10-09 00:14:30.062236 | controller -> localhost | The key's randomart image is: 2025-10-09 00:14:30.062255 | controller -> localhost | +---[RSA 2048]----+ 2025-10-09 00:14:30.062272 | controller -> localhost | | | 2025-10-09 00:14:30.062292 | controller -> localhost | | . + | 2025-10-09 00:14:30.062311 | controller -> localhost | | = +o B + E | 2025-10-09 00:14:30.062329 | controller -> localhost | | . Oo.= X + | 2025-10-09 00:14:30.062347 | controller -> localhost | | + S+ X B | 2025-10-09 00:14:30.062374 | controller -> localhost | | . B *.=. | 2025-10-09 00:14:30.062397 | controller -> localhost | | oo +.*...| 2025-10-09 00:14:30.062416 | controller -> localhost | | oo.o.= o| 2025-10-09 00:14:30.062435 | controller -> localhost | | ..oo+. .| 2025-10-09 00:14:30.062456 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:14:30.062504 | controller -> localhost | ok: Runtime: 0:00:00.077685 2025-10-09 00:14:30.069386 | 2025-10-09 00:14:30.069457 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:14:30.099538 | controller | ok 2025-10-09 00:14:30.110701 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:14:30.119786 | 2025-10-09 00:14:30.119873 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:14:30.144016 | controller | skipping: Conditional result was False 2025-10-09 00:14:30.150850 | 2025-10-09 00:14:30.150927 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:14:30.771001 | controller | changed 2025-10-09 00:14:30.784247 | 2025-10-09 00:14:30.784379 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:14:31.125988 | controller | ok 2025-10-09 00:14:31.133646 | 2025-10-09 00:14:31.133769 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:14:32.508052 | controller | changed 2025-10-09 00:14:32.524090 | 2025-10-09 00:14:32.524196 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:14:33.850306 | controller | changed 2025-10-09 00:14:33.857869 | 2025-10-09 00:14:33.857988 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:14:33.882664 | controller | skipping: Conditional result was False 2025-10-09 00:14:33.893107 | 2025-10-09 00:14:33.893246 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:14:34.267111 | controller -> localhost | changed 2025-10-09 00:14:34.281379 | 2025-10-09 00:14:34.281532 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:14:34.623534 | controller -> localhost | Identity added: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_rsa (zuul-build-sshkey) 2025-10-09 00:14:34.623806 | controller -> localhost | ok: Runtime: 0:00:00.011620 2025-10-09 00:14:34.630232 | 2025-10-09 00:14:34.630296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:14:35.232502 | controller | ok 2025-10-09 00:14:35.239518 | 2025-10-09 00:14:35.239609 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:14:35.266075 | controller | skipping: Conditional result was False 2025-10-09 00:14:35.278088 | 2025-10-09 00:14:35.278187 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-09 00:14:35.302574 | controller | ok 2025-10-09 00:14:35.324271 | 2025-10-09 00:14:35.324356 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:14:35.563768 | controller -> localhost | ok 2025-10-09 00:14:35.574609 | 2025-10-09 00:14:35.574781 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:14:35.607442 | controller | ok 2025-10-09 00:14:35.622659 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:14:35.631147 | 2025-10-09 00:14:35.631284 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:14:35.973920 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-09 00:14:35.974157 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_ecdsa. 2025-10-09 00:14:35.974190 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_ecdsa.pub. 2025-10-09 00:14:35.974222 | controller -> localhost | The key fingerprint is: 2025-10-09 00:14:35.974243 | controller -> localhost | SHA256:IsyrQ+PyF9fYJHgKkUGUZRhgjxsYOXZf5yE32Gxn/lQ zuul-build-sshkey 2025-10-09 00:14:35.974263 | controller -> localhost | The key's randomart image is: 2025-10-09 00:14:35.974283 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-09 00:14:35.974301 | controller -> localhost | |o*=Bo + | 2025-10-09 00:14:35.974320 | controller -> localhost | |=oBo + O o E | 2025-10-09 00:14:35.974337 | controller -> localhost | |o+.o... * * . | 2025-10-09 00:14:35.974355 | controller -> localhost | | +o..o .. . . | 2025-10-09 00:14:35.974373 | controller -> localhost | | . .+o.*S o | 2025-10-09 00:14:35.974391 | controller -> localhost | | o ooo.o . | 2025-10-09 00:14:35.974409 | controller -> localhost | | o ..o | 2025-10-09 00:14:35.974428 | controller -> localhost | |. o.. | 2025-10-09 00:14:35.974446 | controller -> localhost | | ooo | 2025-10-09 00:14:35.974645 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:14:35.974698 | controller -> localhost | ok: Runtime: 0:00:00.010038 2025-10-09 00:14:35.981505 | 2025-10-09 00:14:35.981584 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:14:36.013518 | controller | ok 2025-10-09 00:14:36.024058 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:14:36.035481 | 2025-10-09 00:14:36.035620 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:14:36.060271 | controller | skipping: Conditional result was False 2025-10-09 00:14:36.067402 | 2025-10-09 00:14:36.067506 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:14:36.539692 | controller | changed 2025-10-09 00:14:36.545393 | 2025-10-09 00:14:36.545471 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:14:36.895596 | controller | ok 2025-10-09 00:14:36.907588 | 2025-10-09 00:14:36.907692 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:14:38.303137 | controller | changed 2025-10-09 00:14:38.311850 | 2025-10-09 00:14:38.311951 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:14:39.642793 | controller | changed 2025-10-09 00:14:39.650006 | 2025-10-09 00:14:39.650167 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:14:39.684850 | controller | skipping: Conditional result was False 2025-10-09 00:14:39.694163 | 2025-10-09 00:14:39.694312 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:14:40.041870 | controller -> localhost | changed 2025-10-09 00:14:40.059114 | 2025-10-09 00:14:40.059241 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:14:40.395857 | controller -> localhost | Identity added: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/8067f109b9f84758a517da0531b28fc4_id_ecdsa (zuul-build-sshkey) 2025-10-09 00:14:40.396066 | controller -> localhost | ok: Runtime: 0:00:00.014581 2025-10-09 00:14:40.403404 | 2025-10-09 00:14:40.403470 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:14:40.757984 | controller | ok 2025-10-09 00:14:40.763696 | 2025-10-09 00:14:40.763821 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:14:40.788540 | controller | skipping: Conditional result was False 2025-10-09 00:14:40.806929 | 2025-10-09 00:14:40.807083 | TASK [include_role : remove-zuul-sshkey] 2025-10-09 00:14:40.833448 | controller | skipping: Conditional result was False 2025-10-09 00:14:40.840383 | 2025-10-09 00:14:40.840462 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-09 00:14:41.248522 | controller | ok: "logs" 2025-10-09 00:14:41.248804 | controller | ok: All items complete 2025-10-09 00:14:41.248852 | 2025-10-09 00:14:41.446923 | controller | ok: "artifacts" 2025-10-09 00:14:41.768979 | controller | ok: "docs" 2025-10-09 00:14:41.780662 | 2025-10-09 00:14:41.780801 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-09 00:14:42.148703 | controller | changed: "logs" 2025-10-09 00:14:42.458841 | controller | changed: "artifacts" 2025-10-09 00:14:42.738956 | controller | changed: "docs" 2025-10-09 00:14:42.769072 | 2025-10-09 00:14:42.769176 | PLAY RECAP 2025-10-09 00:14:42.769217 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-09 00:14:42.769243 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-09 00:14:42.769263 | 2025-10-09 00:14:42.922016 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:14:42.922996 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:14:43.575394 | 2025-10-09 00:14:43.575569 | PLAY [all] 2025-10-09 00:14:43.605029 | 2025-10-09 00:14:43.605174 | TASK [Install binary dependencies] 2025-10-09 00:14:43.656106 | controller | ok 2025-10-09 00:14:43.676940 | 2025-10-09 00:14:43.677081 | TASK [bindep : Include find tasks] 2025-10-09 00:14:43.706675 | controller | ok 2025-10-09 00:14:43.714867 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-09 00:14:43.721873 | 2025-10-09 00:14:43.721950 | TASK [bindep : Look for bindep.txt] 2025-10-09 00:14:44.281533 | controller | ok 2025-10-09 00:14:44.299970 | 2025-10-09 00:14:44.300107 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:14:44.315633 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.322883 | 2025-10-09 00:14:44.323166 | TASK [bindep : Look for other-requirements.txt] 2025-10-09 00:14:44.619276 | controller | ok 2025-10-09 00:14:44.624484 | 2025-10-09 00:14:44.624555 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:14:44.651263 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.659188 | 2025-10-09 00:14:44.659345 | TASK [bindep : Look for bindep fallback file] 2025-10-09 00:14:44.684893 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.691681 | 2025-10-09 00:14:44.691847 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:14:44.716786 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.723945 | 2025-10-09 00:14:44.724042 | TASK [bindep : Include bindep tasks] 2025-10-09 00:14:44.749833 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.767454 | 2025-10-09 00:14:44.767612 | TASK [bindep : Include install tasks] 2025-10-09 00:14:44.792890 | controller | skipping: Conditional result was False 2025-10-09 00:14:44.800486 | 2025-10-09 00:14:44.800568 | LOOP [bindep : Include package tasks] 2025-10-09 00:14:44.879829 | 2025-10-09 00:14:44.880005 | TASK [Run test-setup role] 2025-10-09 00:14:44.900852 | controller | ok 2025-10-09 00:14:44.919890 | 2025-10-09 00:14:44.920018 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-09 00:14:45.235305 | controller | ok 2025-10-09 00:14:45.242119 | 2025-10-09 00:14:45.242221 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-09 00:14:45.376711 | controller | skipping: Conditional result was False 2025-10-09 00:14:45.419352 | 2025-10-09 00:14:45.419471 | PLAY RECAP 2025-10-09 00:14:45.419529 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:14:45.419559 | 2025-10-09 00:14:45.553395 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:14:45.556040 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:14:46.180157 | 2025-10-09 00:14:46.180321 | PLAY [controller] 2025-10-09 00:14:46.207871 | 2025-10-09 00:14:46.208046 | TASK [Create the /root directory] 2025-10-09 00:14:46.947899 | controller | ok 2025-10-09 00:14:46.957286 | 2025-10-09 00:14:46.957446 | TASK [Install glibc-langpack-en] 2025-10-09 00:14:55.089640 | controller | ok: Nothing to do 2025-10-09 00:14:55.110316 | 2025-10-09 00:14:55.110453 | TASK [Ensure controller directory exists] 2025-10-09 00:14:55.605520 | controller | changed 2025-10-09 00:14:55.614154 | 2025-10-09 00:14:55.614329 | TASK [Install container runtime] 2025-10-09 00:14:55.668528 | controller | ok 2025-10-09 00:14:55.714283 | 2025-10-09 00:14:55.714394 | LOOP [ensure-podman : Find distribution installation] 2025-10-09 00:14:55.750320 | controller | ok: "/var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-09 00:14:55.760525 | controller | included: /var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-09 00:14:55.770041 | 2025-10-09 00:14:55.770167 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-09 00:16:15.051320 | controller | changed 2025-10-09 00:16:15.067073 | 2025-10-09 00:16:15.067263 | TASK [ensure-podman : Fetch podman version] 2025-10-09 00:16:15.817150 | controller | Client: Podman Engine 2025-10-09 00:16:15.843117 | controller | Version: 4.6.2 2025-10-09 00:16:15.843158 | controller | API Version: 4.6.2 2025-10-09 00:16:15.843165 | controller | Go Version: go1.19.12 2025-10-09 00:16:15.843182 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:16:15.843189 | controller | OS/Arch: linux/amd64 2025-10-09 00:16:16.214433 | controller | ok: Runtime: 0:00:00.221980 2025-10-09 00:16:16.222727 | 2025-10-09 00:16:16.222891 | TASK [ensure-podman : Print podman version installed] 2025-10-09 00:16:16.253120 | Podman version: Client: Podman Engine 2025-10-09 00:16:16.253293 | Version: 4.6.2 2025-10-09 00:16:16.253322 | API Version: 4.6.2 2025-10-09 00:16:16.253343 | Go Version: go1.19.12 2025-10-09 00:16:16.253361 | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:16:16.253379 | OS/Arch: linux/amd64 2025-10-09 00:16:16.260303 | 2025-10-09 00:16:16.260393 | TASK [ensure-podman : Validate podman engine] 2025-10-09 00:16:16.398333 | controller | skipping: Conditional result was False 2025-10-09 00:16:16.406063 | 2025-10-09 00:16:16.406186 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-09 00:16:16.422474 | controller | skipping: Conditional result was False 2025-10-09 00:16:16.436504 | 2025-10-09 00:16:16.436649 | TASK [Ensure python3.8 is present] 2025-10-09 00:16:16.462761 | controller | skipping: Conditional result was False 2025-10-09 00:16:16.469690 | 2025-10-09 00:16:16.469845 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-09 00:16:16.494067 | controller | ok 2025-10-09 00:16:16.523202 | 2025-10-09 00:16:16.523340 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-09 00:16:20.311682 | controller | ok: Nothing to do 2025-10-09 00:16:20.326550 | 2025-10-09 00:16:20.326718 | TASK [our-ensure-python : Also install python3-devel] 2025-10-09 00:16:33.410759 | controller | changed 2025-10-09 00:16:33.430495 | 2025-10-09 00:16:33.430765 | TASK [Run ensure-virtualenv role] 2025-10-09 00:16:33.462421 | controller | ok 2025-10-09 00:16:33.506507 | 2025-10-09 00:16:33.506662 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-09 00:16:33.922456 | controller | /usr/bin/virtualenv 2025-10-09 00:16:34.146232 | controller | ok: Runtime: 0:00:00.004669 2025-10-09 00:16:34.153680 | 2025-10-09 00:16:34.153785 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-09 00:16:34.194933 | controller | skipping: Conditional result was False 2025-10-09 00:16:34.195283 | controller | ok: All items complete 2025-10-09 00:16:34.195332 | 2025-10-09 00:16:34.226051 | 2025-10-09 00:16:34.226273 | TASK [Find the full path of the Python interpreter] 2025-10-09 00:16:34.670193 | controller | /usr/bin/python3 2025-10-09 00:16:34.883992 | controller | ok 2025-10-09 00:16:34.902521 | 2025-10-09 00:16:34.902772 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-09 00:16:36.458955 | controller | created virtual environment CPython3.11.0.final.0-64 in 767ms 2025-10-09 00:16:36.500372 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-09 00:16:36.500419 | 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-09 00:16:36.500430 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-09 00:16:36.500446 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-09 00:16:36.574446 | controller | changed 2025-10-09 00:16:36.588683 | 2025-10-09 00:16:36.588909 | TASK [Set selinux package] 2025-10-09 00:16:36.640599 | controller | ok 2025-10-09 00:16:36.649314 | 2025-10-09 00:16:36.649460 | TASK [Set selinux package (Fedora)] 2025-10-09 00:16:36.692487 | controller | ok 2025-10-09 00:16:36.699809 | 2025-10-09 00:16:36.699944 | TASK [Install selinux into virtualenv] 2025-10-09 00:16:39.281639 | controller | Collecting selinux-please-lie-to-me 2025-10-09 00:16:39.373676 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-09 00:16:39.893110 | controller | Collecting setuptools<50.0.0 2025-10-09 00:16:39.905980 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-09 00:16:40.024020 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.3 MB/s eta 0:00:00 2025-10-09 00:16:40.177090 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-09 00:16:40.177396 | controller | Attempting uninstall: setuptools 2025-10-09 00:16:40.182179 | controller | Found existing installation: setuptools 62.6.0 2025-10-09 00:16:40.294219 | controller | Uninstalling setuptools-62.6.0: 2025-10-09 00:16:40.309338 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-09 00:16:41.063724 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-09 00:16:41.272126 | controller | 2025-10-09 00:16:41.484982 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:16:41.485027 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:16:41.854537 | controller | ok: Runtime: 0:00:04.312546 2025-10-09 00:16:41.861536 | 2025-10-09 00:16:41.861661 | TASK [Install pytest-forked into virtualenv] 2025-10-09 00:16:43.062409 | controller | Collecting pytest-forked 2025-10-09 00:16:43.148957 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-09 00:16:43.205471 | controller | Collecting py 2025-10-09 00:16:43.217747 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-09 00:16:43.253054 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-10-09 00:16:43.430812 | controller | Collecting pytest>=3.10 2025-10-09 00:16:43.443163 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-09 00:16:43.503907 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00 2025-10-09 00:16:43.558709 | controller | Collecting iniconfig>=1 2025-10-09 00:16:43.571367 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-09 00:16:43.636415 | controller | Collecting packaging>=20 2025-10-09 00:16:43.648844 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-09 00:16:43.661223 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.6 MB/s eta 0:00:00 2025-10-09 00:16:43.707398 | controller | Collecting pluggy<2,>=1.5 2025-10-09 00:16:43.719192 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-09 00:16:43.792748 | controller | Collecting pygments>=2.7.2 2025-10-09 00:16:43.804802 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-09 00:16:43.922387 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.6 MB/s eta 0:00:00 2025-10-09 00:16:44.053185 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-09 00:16:46.287348 | 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-09 00:16:46.303230 | controller | 2025-10-09 00:16:46.489900 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:16:46.489944 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:16:47.008686 | controller | ok: Runtime: 0:00:04.156407 2025-10-09 00:16:47.018156 | 2025-10-09 00:16:47.018274 | TASK [Update pip] 2025-10-09 00:16:48.176403 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-09 00:16:48.464758 | controller | Collecting pip 2025-10-09 00:16:48.549117 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-09 00:16:48.723561 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.4 MB/s eta 0:00:00 2025-10-09 00:16:48.846083 | controller | Installing collected packages: pip 2025-10-09 00:16:48.846487 | controller | Attempting uninstall: pip 2025-10-09 00:16:48.851017 | controller | Found existing installation: pip 22.2.2 2025-10-09 00:16:49.112851 | controller | Uninstalling pip-22.2.2: 2025-10-09 00:16:49.142385 | controller | Successfully uninstalled pip-22.2.2 2025-10-09 00:16:50.877371 | controller | Successfully installed pip-25.2 2025-10-09 00:16:51.177230 | controller | ok: Runtime: 0:00:03.480640 2025-10-09 00:16:51.183389 | 2025-10-09 00:16:51.183476 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-09 00:16:51.697157 | controller | changed 2025-10-09 00:16:51.702657 | 2025-10-09 00:16:51.702756 | TASK [Install ansible into virtualenv] 2025-10-09 00:16:52.909654 | controller | Processing ./src/github.com/ansible/ansible 2025-10-09 00:16:52.916207 | controller | Installing build dependencies: started 2025-10-09 00:16:54.918436 | controller | Installing build dependencies: finished with status 'done' 2025-10-09 00:16:56.418573 | controller | Getting requirements to build wheel: started 2025-10-09 00:16:56.418639 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-09 00:16:56.418836 | controller | Preparing metadata (pyproject.toml): started 2025-10-09 00:16:57.328582 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-09 00:16:57.333153 | 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-09 00:16:57.337918 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-09 00:16:57.856829 | controller | ERROR 2025-10-09 00:16:57.857256 | controller | { 2025-10-09 00:16:57.857324 | controller | "delta": "0:00:05.313913", 2025-10-09 00:16:57.857367 | controller | "end": "2025-10-09 00:16:57.485042", 2025-10-09 00:16:57.857418 | controller | "msg": "non-zero return code", 2025-10-09 00:16:57.857509 | controller | "rc": 1, 2025-10-09 00:16:57.857630 | controller | "start": "2025-10-09 00:16:52.171129" 2025-10-09 00:16:57.857679 | controller | } failure 2025-10-09 00:16:57.861210 | 2025-10-09 00:16:57.861381 | PLAY RECAP 2025-10-09 00:16:57.861477 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-09 00:16:57.861520 | 2025-10-09 00:16:58.143655 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:16:58.144658 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:16:58.882823 | 2025-10-09 00:16:58.882999 | PLAY [all] 2025-10-09 00:16:58.908471 | 2025-10-09 00:16:58.908657 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-09 00:16:59.760304 | controller | changed: non-zero return code 2025-10-09 00:16:59.768847 | 2025-10-09 00:16:59.769015 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-09 00:16:59.795538 | controller | skipping: Conditional result was False 2025-10-09 00:16:59.807580 | 2025-10-09 00:16:59.808003 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-09 00:16:59.843851 | 2025-10-09 00:16:59.844021 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-09 00:16:59.869649 | 2025-10-09 00:16:59.870197 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-09 00:16:59.902292 | controller | skipping: Conditional result was False 2025-10-09 00:16:59.910707 | 2025-10-09 00:16:59.910884 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-09 00:16:59.948925 | 2025-10-09 00:16:59.949267 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-09 00:16:59.976855 | controller | skipping: Conditional result was False 2025-10-09 00:16:59.986717 | 2025-10-09 00:16:59.986908 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-09 00:17:00.013864 | controller | skipping: Conditional result was False 2025-10-09 00:17:00.020924 | 2025-10-09 00:17:00.021008 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-09 00:17:00.047552 | controller | skipping: Conditional result was False 2025-10-09 00:17:00.082313 | 2025-10-09 00:17:00.082455 | PLAY RECAP 2025-10-09 00:17:00.082507 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:17:00.082530 | 2025-10-09 00:17:00.345041 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:17:00.345958 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-09 00:17:01.094162 | 2025-10-09 00:17:01.094285 | PLAY [all:!appliance*] 2025-10-09 00:17:01.128389 | 2025-10-09 00:17:01.128523 | TASK [unregister the node] 2025-10-09 00:17:01.271910 | controller | skipping: Conditional result was False 2025-10-09 00:17:01.284835 | 2025-10-09 00:17:01.285069 | TASK [include_role : fetch-output] 2025-10-09 00:17:01.324526 | controller | ok 2025-10-09 00:17:01.369999 | 2025-10-09 00:17:01.370179 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-09 00:17:01.437890 | controller | skipping: Conditional result was False 2025-10-09 00:17:01.444955 | 2025-10-09 00:17:01.445091 | TASK [fetch-output : Set log path for single node] 2025-10-09 00:17:01.488318 | controller | ok 2025-10-09 00:17:01.496844 | 2025-10-09 00:17:01.496990 | LOOP [fetch-output : Ensure local output dirs] 2025-10-09 00:17:01.963988 | controller -> localhost | ok: "/var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/logs" 2025-10-09 00:17:02.228220 | controller -> localhost | changed: "/var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/artifacts" 2025-10-09 00:17:02.508287 | controller -> localhost | changed: "/var/lib/zuul/builds/8067f109b9f84758a517da0531b28fc4/work/docs" 2025-10-09 00:17:02.521241 | 2025-10-09 00:17:02.521398 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-09 00:17:03.879920 | controller | changed: 2025-10-09 00:17:03.880136 | controller | .d..t...... ./ 2025-10-09 00:17:03.880164 | controller | cd+++++++++ controller/ 2025-10-09 00:17:03.880198 | controller | changed: All items complete 2025-10-09 00:17:03.880219 | 2025-10-09 00:17:04.964472 | controller | changed: .d..t...... ./ 2025-10-09 00:17:06.019376 | controller | changed: .d..t...... ./ 2025-10-09 00:17:06.064069 | 2025-10-09 00:17:06.064278 | TASK [include_role : fetch-output-openshift] 2025-10-09 00:17:06.096154 | controller | skipping: Conditional result was False 2025-10-09 00:17:06.105391 | 2025-10-09 00:17:06.105565 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-09 00:17:06.146670 | controller | skipping: Conditional result was False 2025-10-09 00:17:06.157751 | controller | skipping: Conditional result was False 2025-10-09 00:17:06.211988 | 2025-10-09 00:17:06.212223 | PLAY [localhost] 2025-10-09 00:17:06.227309 | 2025-10-09 00:17:06.227491 | TASK [Run Zuul manifest role] 2025-10-09 00:17:06.258806 | localhost | ok 2025-10-09 00:17:06.280462 | 2025-10-09 00:17:06.280598 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-09 00:17:06.729944 | localhost | changed 2025-10-09 00:17:06.735959 | 2025-10-09 00:17:06.736037 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-09 00:17:06.785721 | localhost | ok 2025-10-09 00:17:06.797923 | 2025-10-09 00:17:06.798053 | TASK [Set zuul-log-path fact] 2025-10-09 00:17:06.818604 | localhost | ok 2025-10-09 00:17:06.840870 | 2025-10-09 00:17:06.841043 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:17:06.882634 | localhost | ok 2025-10-09 00:17:06.894017 | 2025-10-09 00:17:06.894134 | LOOP [Run upload-logs-swift role] 2025-10-09 00:17:06.931082 | localhost | Output suppressed because no_log was given 2025-10-09 00:17:06.968891 | 2025-10-09 00:17:06.969026 | TASK [Set zuul-log-path fact] 2025-10-09 00:17:06.994893 | localhost | skipping: Conditional result was False 2025-10-09 00:17:07.002317 | 2025-10-09 00:17:07.002461 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-09 00:17:07.482799 | localhost -> localhost | ok: Runtime: 0:00:00.007578 2025-10-09 00:17:07.490367 | 2025-10-09 00:17:07.490518 | TASK [upload-logs-swift : Upload logs to swift]