2025-11-04 00:11:49.768619 | Job console starting... 2025-11-04 00:11:49.783559 | Updating repositories 2025-11-04 00:11:49.961109 | Preparing job workspace 2025-11-04 00:11:53.882121 | Running Ansible setup... 2025-11-04 00:12:00.306154 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-04 00:12:00.915649 | 2025-11-04 00:12:00.915819 | PLAY [localhost] 2025-11-04 00:12:00.924124 | 2025-11-04 00:12:00.924194 | TASK [Gathering Facts] 2025-11-04 00:12:02.009647 | localhost | ok 2025-11-04 00:12:02.025521 | 2025-11-04 00:12:02.025646 | TASK [Setup log path fact] 2025-11-04 00:12:02.043924 | localhost | ok 2025-11-04 00:12:02.057296 | 2025-11-04 00:12:02.057461 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-04 00:12:02.085491 | localhost | ok 2025-11-04 00:12:02.093849 | 2025-11-04 00:12:02.093937 | TASK [emit-job-header : Print job information] 2025-11-04 00:12:02.134464 | # Job Information 2025-11-04 00:12:02.134667 | Ansible Version: 2.15.12 2025-11-04 00:12:02.134752 | Job: ansible-test-sanity-docker-milestone 2025-11-04 00:12:02.134786 | Pipeline: periodic 2025-11-04 00:12:02.134814 | Executor: ze04.softwarefactory-project.io 2025-11-04 00:12:02.134840 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-04 00:12:02.134869 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/b41/ansible/b41da498d2c84652ab67d19bff816664/ 2025-11-04 00:12:02.134896 | Event ID: 222ce06575fd4159b6a5d52bfe309fd7 2025-11-04 00:12:02.140557 | 2025-11-04 00:12:02.140649 | LOOP [emit-job-header : Print node information] 2025-11-04 00:12:02.249546 | localhost | ok: 2025-11-04 00:12:02.249732 | localhost | # Node Information 2025-11-04 00:12:02.249765 | localhost | Inventory Hostname: controller 2025-11-04 00:12:02.249792 | localhost | Hostname: ip-172-16-236-170 2025-11-04 00:12:02.249812 | localhost | Username: zuul-worker 2025-11-04 00:12:02.249838 | localhost | Distro: Fedora 37 2025-11-04 00:12:02.249864 | localhost | Provider: ansible-us-east-2 2025-11-04 00:12:02.249889 | localhost | Region: us-east-2 2025-11-04 00:12:02.249913 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-04 00:12:02.249937 | localhost | Product Name: t3.small 2025-11-04 00:12:02.249958 | localhost | Interface IP: 13.58.148.21 2025-11-04 00:12:02.297329 | 2025-11-04 00:12:02.297525 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-04 00:12:02.703962 | localhost -> localhost | changed 2025-11-04 00:12:02.709887 | 2025-11-04 00:12:02.709956 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-04 00:12:03.660881 | localhost -> localhost | changed 2025-11-04 00:12:03.682699 | 2025-11-04 00:12:03.682798 | PLAY [all:!appliance*] 2025-11-04 00:12:03.700720 | 2025-11-04 00:12:03.700844 | TASK [include_role : start-zuul-console] 2025-11-04 00:12:03.720388 | controller | ok 2025-11-04 00:12:03.735549 | 2025-11-04 00:12:03.735670 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-04 00:12:04.399710 | controller | ok 2025-11-04 00:12:04.427726 | 2025-11-04 00:12:04.427943 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-04 00:12:06.248995 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-04 00:12:06.263319 | 2025-11-04 00:12:06.263504 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-04 00:12:06.412572 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.419574 | 2025-11-04 00:12:06.419656 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-04 00:12:06.444036 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.454309 | 2025-11-04 00:12:06.454434 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-04 00:12:06.479979 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.493896 | 2025-11-04 00:12:06.494056 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-04 00:12:06.519892 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.529573 | 2025-11-04 00:12:06.529757 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-04 00:12:06.555194 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.564283 | 2025-11-04 00:12:06.564395 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-04 00:12:06.589565 | controller | skipping: Conditional result was False 2025-11-04 00:12:06.607153 | 2025-11-04 00:12:06.607271 | TASK [Disable Fedora Modular] 2025-11-04 00:12:07.362467 | controller | changed 2025-11-04 00:12:07.377047 | 2025-11-04 00:12:07.377215 | TASK [Enable EPEL] 2025-11-04 00:12:07.407720 | controller | skipping: Conditional result was False 2025-11-04 00:12:07.426105 | 2025-11-04 00:12:07.426326 | TASK [Register the RHEL node] 2025-11-04 00:12:07.595238 | 2025-11-04 00:12:07.595505 | TASK [Show the subscription-manager status] 2025-11-04 00:12:07.824234 | controller | skipping: Conditional result was False 2025-11-04 00:12:07.841836 | 2025-11-04 00:12:07.842062 | TASK [Enable EPEL on RHEL] 2025-11-04 00:12:07.993289 | controller | skipping: Conditional result was False 2025-11-04 00:12:08.002540 | 2025-11-04 00:12:08.002632 | TASK [Install git and tox] 2025-11-04 00:13:37.746406 | controller | changed 2025-11-04 00:13:37.756669 | 2025-11-04 00:13:37.756893 | TASK [include_role : prepare-workspace] 2025-11-04 00:13:37.798295 | controller | ok 2025-11-04 00:13:37.822133 | 2025-11-04 00:13:37.822252 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-04 00:13:38.306877 | controller | ok 2025-11-04 00:13:38.318163 | 2025-11-04 00:13:38.318352 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-04 00:13:51.624206 | controller | Output suppressed because no_log was given 2025-11-04 00:13:51.638801 | 2025-11-04 00:13:51.638994 | TASK [include_role : prepare-workspace-openshift] 2025-11-04 00:13:51.669602 | controller | skipping: Conditional result was False 2025-11-04 00:13:51.727478 | 2025-11-04 00:13:51.727589 | PLAY [all:!appliance] 2025-11-04 00:13:51.742748 | 2025-11-04 00:13:51.742813 | TASK [Run add-build-sshkey role (RSA)] 2025-11-04 00:13:51.774159 | controller | ok 2025-11-04 00:13:51.789433 | 2025-11-04 00:13:51.789502 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-04 00:13:52.050481 | controller -> localhost | ok 2025-11-04 00:13:52.065849 | 2025-11-04 00:13:52.066028 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-04 00:13:52.112544 | controller | ok 2025-11-04 00:13:52.133972 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-04 00:13:52.142838 | 2025-11-04 00:13:52.142948 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-04 00:13:53.007485 | controller -> localhost | Generating public/private rsa key pair. 2025-11-04 00:13:53.008664 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_rsa. 2025-11-04 00:13:53.008790 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_rsa.pub. 2025-11-04 00:13:53.008839 | controller -> localhost | The key fingerprint is: 2025-11-04 00:13:53.008881 | controller -> localhost | SHA256:rpJQ4/5ADCkWypZ7Ns9keoIXZBFb6hElEkMS5lYf5fM zuul-build-sshkey 2025-11-04 00:13:53.008921 | controller -> localhost | The key's randomart image is: 2025-11-04 00:13:53.008962 | controller -> localhost | +---[RSA 2048]----+ 2025-11-04 00:13:53.009001 | controller -> localhost | |+O.*o+.. | 2025-11-04 00:13:53.009041 | controller -> localhost | |* *.O o | 2025-11-04 00:13:53.009079 | controller -> localhost | |oBo* . o | 2025-11-04 00:13:53.009118 | controller -> localhost | |+.=o+ o | 2025-11-04 00:13:53.009155 | controller -> localhost | | . Oo+ SE | 2025-11-04 00:13:53.009213 | controller -> localhost | | =.X . | 2025-11-04 00:13:53.009262 | controller -> localhost | | . *.= . | 2025-11-04 00:13:53.009304 | controller -> localhost | | . *. . | 2025-11-04 00:13:53.009345 | controller -> localhost | | oo | 2025-11-04 00:13:53.009392 | controller -> localhost | +----[SHA256]-----+ 2025-11-04 00:13:53.009487 | controller -> localhost | ok: Runtime: 0:00:00.430624 2025-11-04 00:13:53.025482 | 2025-11-04 00:13:53.025720 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-04 00:13:53.077845 | controller | ok 2025-11-04 00:13:53.100399 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-04 00:13:53.115605 | 2025-11-04 00:13:53.115824 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-04 00:13:53.133955 | controller | skipping: Conditional result was False 2025-11-04 00:13:53.151315 | 2025-11-04 00:13:53.151476 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-04 00:13:53.810798 | controller | changed 2025-11-04 00:13:53.831658 | 2025-11-04 00:13:53.831872 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-04 00:13:54.177787 | controller | ok 2025-11-04 00:13:54.192506 | 2025-11-04 00:13:54.192853 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-04 00:13:55.512516 | controller | changed 2025-11-04 00:13:55.528419 | 2025-11-04 00:13:55.528669 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-04 00:13:56.844775 | controller | changed 2025-11-04 00:13:56.860378 | 2025-11-04 00:13:56.860537 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-04 00:13:56.889717 | controller | skipping: Conditional result was False 2025-11-04 00:13:56.904928 | 2025-11-04 00:13:56.905094 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-04 00:13:57.404335 | controller -> localhost | changed 2025-11-04 00:13:57.426242 | 2025-11-04 00:13:57.426546 | TASK [add-build-sshkey : Add back temp key] 2025-11-04 00:13:57.779087 | controller -> localhost | Identity added: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_rsa (zuul-build-sshkey) 2025-11-04 00:13:57.779372 | controller -> localhost | ok: Runtime: 0:00:00.016823 2025-11-04 00:13:57.789476 | 2025-11-04 00:13:57.789568 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-04 00:13:58.334556 | controller | ok 2025-11-04 00:13:58.349348 | 2025-11-04 00:13:58.349508 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-04 00:13:58.378955 | controller | skipping: Conditional result was False 2025-11-04 00:13:58.396929 | 2025-11-04 00:13:58.397066 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-04 00:13:58.431065 | controller | ok 2025-11-04 00:13:58.454900 | 2025-11-04 00:13:58.455024 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-04 00:13:58.777941 | controller -> localhost | ok 2025-11-04 00:13:58.786725 | 2025-11-04 00:13:58.786848 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-04 00:13:58.834388 | controller | ok 2025-11-04 00:13:58.853049 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-04 00:13:58.864741 | 2025-11-04 00:13:58.864912 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-04 00:13:59.135873 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-04 00:13:59.136126 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_ecdsa. 2025-11-04 00:13:59.136156 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_ecdsa.pub. 2025-11-04 00:13:59.136186 | controller -> localhost | The key fingerprint is: 2025-11-04 00:13:59.136205 | controller -> localhost | SHA256:3Cbe4Uzt1zXjneZyL/+eFc+BDUt6J6FkBVT364qRlBU zuul-build-sshkey 2025-11-04 00:13:59.136224 | controller -> localhost | The key's randomart image is: 2025-11-04 00:13:59.136242 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-04 00:13:59.136261 | controller -> localhost | | .ooE . | 2025-11-04 00:13:59.136278 | controller -> localhost | | . o .| 2025-11-04 00:13:59.136296 | controller -> localhost | | o = .| 2025-11-04 00:13:59.136313 | controller -> localhost | | . .o.* * .| 2025-11-04 00:13:59.136329 | controller -> localhost | | S ==.= O.| 2025-11-04 00:13:59.136346 | controller -> localhost | | . B.oo =oX| 2025-11-04 00:13:59.136363 | controller -> localhost | | . +o. .=*| 2025-11-04 00:13:59.136380 | controller -> localhost | | oo=.o| 2025-11-04 00:13:59.136396 | controller -> localhost | | . .o*B| 2025-11-04 00:13:59.136413 | controller -> localhost | +----[SHA256]-----+ 2025-11-04 00:13:59.136471 | controller -> localhost | ok: Runtime: 0:00:00.012467 2025-11-04 00:13:59.143785 | 2025-11-04 00:13:59.143874 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-04 00:13:59.174373 | controller | ok 2025-11-04 00:13:59.181975 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-04 00:13:59.191308 | 2025-11-04 00:13:59.191375 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-04 00:13:59.227047 | controller | skipping: Conditional result was False 2025-11-04 00:13:59.235807 | 2025-11-04 00:13:59.235919 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-04 00:13:59.708287 | controller | changed 2025-11-04 00:13:59.716244 | 2025-11-04 00:13:59.716330 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-04 00:14:00.131657 | controller | ok 2025-11-04 00:14:00.142125 | 2025-11-04 00:14:00.142367 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-04 00:14:01.857942 | controller | changed 2025-11-04 00:14:01.872640 | 2025-11-04 00:14:01.872854 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-04 00:14:03.493787 | controller | changed 2025-11-04 00:14:03.499781 | 2025-11-04 00:14:03.499851 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-04 00:14:03.528664 | controller | skipping: Conditional result was False 2025-11-04 00:14:03.536544 | 2025-11-04 00:14:03.536622 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-04 00:14:03.807322 | controller -> localhost | changed 2025-11-04 00:14:03.821708 | 2025-11-04 00:14:03.821840 | TASK [add-build-sshkey : Add back temp key] 2025-11-04 00:14:04.174665 | controller -> localhost | Identity added: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/b41da498d2c84652ab67d19bff816664_id_ecdsa (zuul-build-sshkey) 2025-11-04 00:14:04.175008 | controller -> localhost | ok: Runtime: 0:00:00.010882 2025-11-04 00:14:04.224489 | 2025-11-04 00:14:04.224623 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-04 00:14:04.581042 | controller | ok 2025-11-04 00:14:04.595966 | 2025-11-04 00:14:04.596119 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-04 00:14:04.636815 | controller | skipping: Conditional result was False 2025-11-04 00:14:04.667828 | 2025-11-04 00:14:04.668054 | TASK [include_role : remove-zuul-sshkey] 2025-11-04 00:14:04.696295 | controller | skipping: Conditional result was False 2025-11-04 00:14:04.707265 | 2025-11-04 00:14:04.707375 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-04 00:14:05.057072 | controller | ok: "logs" 2025-11-04 00:14:05.057716 | controller | ok: All items complete 2025-11-04 00:14:05.057810 | 2025-11-04 00:14:05.348918 | controller | ok: "artifacts" 2025-11-04 00:14:05.636737 | controller | ok: "docs" 2025-11-04 00:14:05.656846 | 2025-11-04 00:14:05.657063 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-04 00:14:06.001800 | controller | changed: "logs" 2025-11-04 00:14:06.309319 | controller | changed: "artifacts" 2025-11-04 00:14:06.600971 | controller | changed: "docs" 2025-11-04 00:14:06.674867 | 2025-11-04 00:14:06.675017 | PLAY RECAP 2025-11-04 00:14:06.675132 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-04 00:14:06.675175 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-04 00:14:06.675203 | 2025-11-04 00:14:06.835647 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-04 00:14:06.836909 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-04 00:14:07.386960 | 2025-11-04 00:14:07.387086 | PLAY [all] 2025-11-04 00:14:07.408917 | 2025-11-04 00:14:07.409036 | TASK [Install binary dependencies] 2025-11-04 00:14:07.463307 | controller | ok 2025-11-04 00:14:07.491898 | 2025-11-04 00:14:07.492043 | TASK [bindep : Include find tasks] 2025-11-04 00:14:07.523019 | controller | ok 2025-11-04 00:14:07.531071 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-04 00:14:07.538084 | 2025-11-04 00:14:07.538169 | TASK [bindep : Look for bindep.txt] 2025-11-04 00:14:08.080703 | controller | ok 2025-11-04 00:14:08.089124 | 2025-11-04 00:14:08.089206 | TASK [bindep : Define bindep_file fact] 2025-11-04 00:14:08.116272 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.124522 | 2025-11-04 00:14:08.124602 | TASK [bindep : Look for other-requirements.txt] 2025-11-04 00:14:08.436423 | controller | ok 2025-11-04 00:14:08.448538 | 2025-11-04 00:14:08.448738 | TASK [bindep : Define bindep_file fact] 2025-11-04 00:14:08.476442 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.490379 | 2025-11-04 00:14:08.490530 | TASK [bindep : Look for bindep fallback file] 2025-11-04 00:14:08.518784 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.532562 | 2025-11-04 00:14:08.532816 | TASK [bindep : Define bindep_file fact] 2025-11-04 00:14:08.560591 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.573952 | 2025-11-04 00:14:08.574091 | TASK [bindep : Include bindep tasks] 2025-11-04 00:14:08.602915 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.619797 | 2025-11-04 00:14:08.619964 | TASK [bindep : Include install tasks] 2025-11-04 00:14:08.648472 | controller | skipping: Conditional result was False 2025-11-04 00:14:08.662623 | 2025-11-04 00:14:08.662820 | LOOP [bindep : Include package tasks] 2025-11-04 00:14:08.735513 | 2025-11-04 00:14:08.735800 | TASK [Run test-setup role] 2025-11-04 00:14:08.764492 | controller | ok 2025-11-04 00:14:08.796159 | 2025-11-04 00:14:08.796258 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-04 00:14:09.103597 | controller | ok 2025-11-04 00:14:09.112069 | 2025-11-04 00:14:09.112165 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-04 00:14:09.261046 | controller | skipping: Conditional result was False 2025-11-04 00:14:09.316699 | 2025-11-04 00:14:09.316832 | PLAY RECAP 2025-11-04 00:14:09.316889 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-04 00:14:09.316918 | 2025-11-04 00:14:09.449770 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-04 00:14:09.450723 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-04 00:14:10.114016 | 2025-11-04 00:14:10.114177 | PLAY [controller] 2025-11-04 00:14:10.134390 | 2025-11-04 00:14:10.134500 | TASK [Create the /root directory] 2025-11-04 00:14:10.876035 | controller | ok 2025-11-04 00:14:10.884187 | 2025-11-04 00:14:10.884293 | TASK [Install glibc-langpack-en] 2025-11-04 00:14:18.964142 | controller | ok: Nothing to do 2025-11-04 00:14:18.978127 | 2025-11-04 00:14:18.978323 | TASK [Ensure controller directory exists] 2025-11-04 00:14:19.430965 | controller | changed 2025-11-04 00:14:19.446337 | 2025-11-04 00:14:19.446508 | TASK [Install container runtime] 2025-11-04 00:14:19.543318 | controller | ok 2025-11-04 00:14:19.603222 | 2025-11-04 00:14:19.603354 | LOOP [ensure-podman : Find distribution installation] 2025-11-04 00:14:19.638169 | controller | ok: "/var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-04 00:14:19.650470 | controller | included: /var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-04 00:14:19.665015 | 2025-11-04 00:14:19.665180 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-04 00:15:33.586423 | controller | changed 2025-11-04 00:15:33.593284 | 2025-11-04 00:15:33.593368 | TASK [ensure-podman : Fetch podman version] 2025-11-04 00:15:34.330541 | controller | Client: Podman Engine 2025-11-04 00:15:34.354268 | controller | Version: 4.6.2 2025-11-04 00:15:34.354382 | controller | API Version: 4.6.2 2025-11-04 00:15:34.354391 | controller | Go Version: go1.19.12 2025-11-04 00:15:34.354409 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-04 00:15:34.354416 | controller | OS/Arch: linux/amd64 2025-11-04 00:15:34.731286 | controller | ok: Runtime: 0:00:00.214389 2025-11-04 00:15:34.740552 | 2025-11-04 00:15:34.740697 | TASK [ensure-podman : Print podman version installed] 2025-11-04 00:15:34.777978 | Podman version: Client: Podman Engine 2025-11-04 00:15:34.778254 | Version: 4.6.2 2025-11-04 00:15:34.778315 | API Version: 4.6.2 2025-11-04 00:15:34.778361 | Go Version: go1.19.12 2025-11-04 00:15:34.778402 | Built: Mon Aug 28 19:38:31 2023 2025-11-04 00:15:34.778444 | OS/Arch: linux/amd64 2025-11-04 00:15:34.790746 | 2025-11-04 00:15:34.790881 | TASK [ensure-podman : Validate podman engine] 2025-11-04 00:15:34.935580 | controller | skipping: Conditional result was False 2025-11-04 00:15:34.941955 | 2025-11-04 00:15:34.942028 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-04 00:15:34.966708 | controller | skipping: Conditional result was False 2025-11-04 00:15:34.977504 | 2025-11-04 00:15:34.977585 | TASK [Ensure python3.8 is present] 2025-11-04 00:15:35.001536 | controller | skipping: Conditional result was False 2025-11-04 00:15:35.009430 | 2025-11-04 00:15:35.009523 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-04 00:15:35.038351 | controller | ok 2025-11-04 00:15:35.067963 | 2025-11-04 00:15:35.068105 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-04 00:15:38.817670 | controller | ok: Nothing to do 2025-11-04 00:15:38.830619 | 2025-11-04 00:15:38.830809 | TASK [our-ensure-python : Also install python3-devel] 2025-11-04 00:15:52.192163 | controller | changed 2025-11-04 00:15:52.203457 | 2025-11-04 00:15:52.203522 | TASK [Run ensure-virtualenv role] 2025-11-04 00:15:52.225189 | controller | ok 2025-11-04 00:15:52.247598 | 2025-11-04 00:15:52.247756 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-04 00:15:52.621662 | controller | /usr/bin/virtualenv 2025-11-04 00:15:52.899006 | controller | ok: Runtime: 0:00:00.004025 2025-11-04 00:15:52.911020 | 2025-11-04 00:15:52.911137 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-04 00:15:52.946561 | controller | skipping: Conditional result was False 2025-11-04 00:15:52.946937 | controller | ok: All items complete 2025-11-04 00:15:52.946976 | 2025-11-04 00:15:52.974263 | 2025-11-04 00:15:52.974481 | TASK [Find the full path of the Python interpreter] 2025-11-04 00:15:53.446784 | controller | /usr/bin/python3 2025-11-04 00:15:53.667997 | controller | ok 2025-11-04 00:15:53.676624 | 2025-11-04 00:15:53.676773 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-04 00:15:55.185196 | controller | created virtual environment CPython3.11.0.final.0-64 in 794ms 2025-11-04 00:15:55.227907 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-04 00:15:55.227961 | 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-11-04 00:15:55.227978 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-04 00:15:55.228002 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-04 00:15:55.331203 | controller | changed 2025-11-04 00:15:55.341919 | 2025-11-04 00:15:55.342048 | TASK [Set selinux package] 2025-11-04 00:15:55.392351 | controller | ok 2025-11-04 00:15:55.405316 | 2025-11-04 00:15:55.405550 | TASK [Set selinux package (Fedora)] 2025-11-04 00:15:55.451390 | controller | ok 2025-11-04 00:15:55.460528 | 2025-11-04 00:15:55.460629 | TASK [Install selinux into virtualenv] 2025-11-04 00:15:58.065503 | controller | Collecting selinux-please-lie-to-me 2025-11-04 00:15:58.151856 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-04 00:15:58.686600 | controller | Collecting setuptools<50.0.0 2025-11-04 00:15:58.700309 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-04 00:15:58.834837 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.3 MB/s eta 0:00:00 2025-11-04 00:15:58.988773 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-04 00:15:58.989187 | controller | Attempting uninstall: setuptools 2025-11-04 00:15:58.994138 | controller | Found existing installation: setuptools 62.6.0 2025-11-04 00:15:59.105042 | controller | Uninstalling setuptools-62.6.0: 2025-11-04 00:15:59.120226 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-04 00:15:59.843158 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-04 00:16:00.055726 | controller | 2025-11-04 00:16:00.280276 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-04 00:16:00.280325 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-04 00:16:00.648475 | controller | ok: Runtime: 0:00:04.356081 2025-11-04 00:16:00.657243 | 2025-11-04 00:16:00.657338 | TASK [Install pytest-forked into virtualenv] 2025-11-04 00:16:01.911312 | controller | Collecting pytest-forked 2025-11-04 00:16:01.998424 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-04 00:16:02.058233 | controller | Collecting py 2025-11-04 00:16:02.071462 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-04 00:16:02.104261 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-11-04 00:16:02.295804 | controller | Collecting pytest>=3.10 2025-11-04 00:16:02.308545 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-04 00:16:02.354253 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.6 MB/s eta 0:00:00 2025-11-04 00:16:02.437860 | controller | Collecting iniconfig>=1 2025-11-04 00:16:02.452712 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-04 00:16:02.523210 | controller | Collecting packaging>=20 2025-11-04 00:16:02.535603 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-04 00:16:02.547957 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.3 MB/s eta 0:00:00 2025-11-04 00:16:02.596263 | controller | Collecting pluggy<2,>=1.5 2025-11-04 00:16:02.608554 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-04 00:16:02.687069 | controller | Collecting pygments>=2.7.2 2025-11-04 00:16:02.699199 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-04 00:16:02.729045 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 49.4 MB/s eta 0:00:00 2025-11-04 00:16:02.866345 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-04 00:16:05.109188 | controller | Successfully installed iniconfig-2.3.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-11-04 00:16:05.129659 | controller | 2025-11-04 00:16:05.328699 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-04 00:16:05.328746 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-04 00:16:05.868933 | controller | ok: Runtime: 0:00:04.162963 2025-11-04 00:16:05.876440 | 2025-11-04 00:16:05.876523 | TASK [Update pip] 2025-11-04 00:16:07.161389 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-04 00:16:07.449830 | controller | Collecting pip 2025-11-04 00:16:07.540554 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-04 00:16:07.698604 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.6 MB/s eta 0:00:00 2025-11-04 00:16:07.830247 | controller | Installing collected packages: pip 2025-11-04 00:16:07.830697 | controller | Attempting uninstall: pip 2025-11-04 00:16:07.835138 | controller | Found existing installation: pip 22.2.2 2025-11-04 00:16:08.134228 | controller | Uninstalling pip-22.2.2: 2025-11-04 00:16:08.170779 | controller | Successfully uninstalled pip-22.2.2 2025-11-04 00:16:09.842122 | controller | Successfully installed pip-25.3 2025-11-04 00:16:10.524738 | controller | ok: Runtime: 0:00:03.650516 2025-11-04 00:16:10.530734 | 2025-11-04 00:16:10.530810 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-04 00:16:11.045898 | controller | changed 2025-11-04 00:16:11.054630 | 2025-11-04 00:16:11.054765 | TASK [Install ansible into virtualenv] 2025-11-04 00:16:12.085163 | controller | Processing ./src/github.com/ansible/ansible 2025-11-04 00:16:12.091431 | controller | Installing build dependencies: started 2025-11-04 00:16:14.039486 | controller | Installing build dependencies: finished with status 'done' 2025-11-04 00:16:14.040268 | controller | Getting requirements to build wheel: started 2025-11-04 00:16:15.552958 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-04 00:16:16.494520 | controller | Preparing metadata (pyproject.toml): started 2025-11-04 00:16:16.494577 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-04 00:16:16.498450 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-11-04 00:16:16.498526 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-04 00:16:16.710715 | controller | ERROR 2025-11-04 00:16:16.711091 | controller | { 2025-11-04 00:16:16.711782 | controller | "delta": "0:00:05.099821", 2025-11-04 00:16:16.711902 | controller | "end": "2025-11-04 00:16:16.637058", 2025-11-04 00:16:16.711965 | controller | "msg": "non-zero return code", 2025-11-04 00:16:16.712040 | controller | "rc": 1, 2025-11-04 00:16:16.712091 | controller | "start": "2025-11-04 00:16:11.537237" 2025-11-04 00:16:16.712140 | controller | } failure 2025-11-04 00:16:16.718405 | 2025-11-04 00:16:16.718542 | PLAY RECAP 2025-11-04 00:16:16.718665 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-04 00:16:16.718796 | 2025-11-04 00:16:16.884200 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-04 00:16:16.885178 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-04 00:16:17.553941 | 2025-11-04 00:16:17.554083 | PLAY [all] 2025-11-04 00:16:17.580012 | 2025-11-04 00:16:17.580167 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-04 00:16:18.352172 | controller | changed: non-zero return code 2025-11-04 00:16:18.364488 | 2025-11-04 00:16:18.364737 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-04 00:16:18.390763 | controller | skipping: Conditional result was False 2025-11-04 00:16:18.399140 | 2025-11-04 00:16:18.399271 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-04 00:16:18.425819 | 2025-11-04 00:16:18.426078 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-04 00:16:18.460348 | 2025-11-04 00:16:18.460540 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-04 00:16:18.476782 | controller | skipping: Conditional result was False 2025-11-04 00:16:18.488425 | 2025-11-04 00:16:18.488554 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-04 00:16:18.514452 | 2025-11-04 00:16:18.514706 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-04 00:16:18.530455 | controller | skipping: Conditional result was False 2025-11-04 00:16:18.539056 | 2025-11-04 00:16:18.539153 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-04 00:16:18.564471 | controller | skipping: Conditional result was False 2025-11-04 00:16:18.572349 | 2025-11-04 00:16:18.572442 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-04 00:16:18.597694 | controller | skipping: Conditional result was False 2025-11-04 00:16:18.631170 | 2025-11-04 00:16:18.631272 | PLAY RECAP 2025-11-04 00:16:18.631328 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-04 00:16:18.631356 | 2025-11-04 00:16:18.744013 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-04 00:16:18.745773 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-04 00:16:19.372411 | 2025-11-04 00:16:19.372532 | PLAY [all:!appliance*] 2025-11-04 00:16:19.394380 | 2025-11-04 00:16:19.394523 | TASK [unregister the node] 2025-11-04 00:16:19.543405 | controller | skipping: Conditional result was False 2025-11-04 00:16:19.558401 | 2025-11-04 00:16:19.558578 | TASK [include_role : fetch-output] 2025-11-04 00:16:19.620219 | controller | ok 2025-11-04 00:16:19.659817 | 2025-11-04 00:16:19.659976 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-04 00:16:19.717832 | controller | skipping: Conditional result was False 2025-11-04 00:16:19.727263 | 2025-11-04 00:16:19.727382 | TASK [fetch-output : Set log path for single node] 2025-11-04 00:16:19.772637 | controller | ok 2025-11-04 00:16:19.781314 | 2025-11-04 00:16:19.781423 | LOOP [fetch-output : Ensure local output dirs] 2025-11-04 00:16:20.228176 | controller -> localhost | ok: "/var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/logs" 2025-11-04 00:16:20.499510 | controller -> localhost | changed: "/var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/artifacts" 2025-11-04 00:16:20.759021 | controller -> localhost | changed: "/var/lib/zuul/builds/b41da498d2c84652ab67d19bff816664/work/docs" 2025-11-04 00:16:20.792405 | 2025-11-04 00:16:20.792601 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-04 00:16:22.178515 | controller | changed: 2025-11-04 00:16:22.178729 | controller | .d..t...... ./ 2025-11-04 00:16:22.178761 | controller | cd+++++++++ controller/ 2025-11-04 00:16:22.178795 | controller | changed: All items complete 2025-11-04 00:16:22.178815 | 2025-11-04 00:16:23.227046 | controller | changed: .d..t...... ./ 2025-11-04 00:16:24.442262 | controller | changed: .d..t...... ./ 2025-11-04 00:16:24.461449 | 2025-11-04 00:16:24.461654 | TASK [include_role : fetch-output-openshift] 2025-11-04 00:16:24.476572 | controller | skipping: Conditional result was False 2025-11-04 00:16:24.483265 | 2025-11-04 00:16:24.483335 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-04 00:16:24.511058 | controller | skipping: Conditional result was False 2025-11-04 00:16:24.520384 | controller | skipping: Conditional result was False 2025-11-04 00:16:24.556077 | 2025-11-04 00:16:24.556200 | PLAY [localhost] 2025-11-04 00:16:24.568924 | 2025-11-04 00:16:24.568990 | TASK [Run Zuul manifest role] 2025-11-04 00:16:24.587977 | localhost | ok 2025-11-04 00:16:24.602668 | 2025-11-04 00:16:24.602767 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-04 00:16:25.066819 | localhost | changed 2025-11-04 00:16:25.076936 | 2025-11-04 00:16:25.077132 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-04 00:16:25.122189 | localhost | ok 2025-11-04 00:16:25.130728 | 2025-11-04 00:16:25.130796 | TASK [Set zuul-log-path fact] 2025-11-04 00:16:25.151264 | localhost | ok 2025-11-04 00:16:25.166078 | 2025-11-04 00:16:25.166183 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-04 00:16:25.197194 | localhost | ok 2025-11-04 00:16:25.208650 | 2025-11-04 00:16:25.208771 | LOOP [Run upload-logs-swift role] 2025-11-04 00:16:25.244259 | localhost | Output suppressed because no_log was given 2025-11-04 00:16:25.279210 | 2025-11-04 00:16:25.279833 | TASK [Set zuul-log-path fact] 2025-11-04 00:16:25.308566 | localhost | skipping: Conditional result was False 2025-11-04 00:16:25.315135 | 2025-11-04 00:16:25.315214 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-04 00:16:25.715125 | localhost -> localhost | ok: Runtime: 0:00:00.009877 2025-11-04 00:16:25.721134 | 2025-11-04 00:16:25.721205 | TASK [upload-logs-swift : Upload logs to swift]