2025-10-31 00:18:28.317929 | Job console starting... 2025-10-31 00:18:28.328564 | Updating repositories 2025-10-31 00:18:28.514844 | Preparing job workspace 2025-10-31 00:18:32.408319 | Running Ansible setup... 2025-10-31 00:18:38.776076 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-31 00:18:39.346627 | 2025-10-31 00:18:39.346757 | PLAY [localhost] 2025-10-31 00:18:39.354826 | 2025-10-31 00:18:39.354895 | TASK [Gathering Facts] 2025-10-31 00:18:40.293864 | localhost | ok 2025-10-31 00:18:40.309321 | 2025-10-31 00:18:40.309423 | TASK [Setup log path fact] 2025-10-31 00:18:40.333448 | localhost | ok 2025-10-31 00:18:40.354292 | 2025-10-31 00:18:40.354417 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-31 00:18:40.382195 | localhost | ok 2025-10-31 00:18:40.389686 | 2025-10-31 00:18:40.389765 | TASK [emit-job-header : Print job information] 2025-10-31 00:18:40.417475 | # Job Information 2025-10-31 00:18:40.417587 | Ansible Version: 2.15.12 2025-10-31 00:18:40.417617 | Job: ansible-test-sanity-docker-milestone 2025-10-31 00:18:40.417637 | Pipeline: periodic 2025-10-31 00:18:40.417655 | Executor: ze03.softwarefactory-project.io 2025-10-31 00:18:40.417672 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-31 00:18:40.417692 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fa9/ansible/fa9b7f3af9f242a6a88bb5082ec1036e/ 2025-10-31 00:18:40.417710 | Event ID: de96af6d0b7a45ea8c822badaf8296b2 2025-10-31 00:18:40.422680 | 2025-10-31 00:18:40.422893 | LOOP [emit-job-header : Print node information] 2025-10-31 00:18:40.520266 | localhost | ok: 2025-10-31 00:18:40.520452 | localhost | # Node Information 2025-10-31 00:18:40.520478 | localhost | Inventory Hostname: controller 2025-10-31 00:18:40.520497 | localhost | Hostname: ip-172-16-173-131 2025-10-31 00:18:40.520516 | localhost | Username: zuul-worker 2025-10-31 00:18:40.520535 | localhost | Distro: Fedora 37 2025-10-31 00:18:40.520552 | localhost | Provider: ansible-us-east-2 2025-10-31 00:18:40.520569 | localhost | Region: us-east-2 2025-10-31 00:18:40.520585 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-31 00:18:40.520601 | localhost | Product Name: t3.small 2025-10-31 00:18:40.520617 | localhost | Interface IP: 13.58.245.236 2025-10-31 00:18:40.535084 | 2025-10-31 00:18:40.535163 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-31 00:18:40.934541 | localhost -> localhost | changed 2025-10-31 00:18:40.940001 | 2025-10-31 00:18:40.940074 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-31 00:18:41.752248 | localhost -> localhost | changed 2025-10-31 00:18:41.774428 | 2025-10-31 00:18:41.774524 | PLAY [all:!appliance*] 2025-10-31 00:18:41.790431 | 2025-10-31 00:18:41.790553 | TASK [include_role : start-zuul-console] 2025-10-31 00:18:41.810186 | controller | ok 2025-10-31 00:18:41.824483 | 2025-10-31 00:18:41.824578 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-31 00:18:42.518559 | controller | ok 2025-10-31 00:18:42.544475 | 2025-10-31 00:18:42.544642 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-31 00:18:44.144686 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-31 00:18:44.157976 | 2025-10-31 00:18:44.158106 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-31 00:18:44.302601 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.315913 | 2025-10-31 00:18:44.316052 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-31 00:18:44.343179 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.358072 | 2025-10-31 00:18:44.358279 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-31 00:18:44.396548 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.409547 | 2025-10-31 00:18:44.409778 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-31 00:18:44.449401 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.462596 | 2025-10-31 00:18:44.462768 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-31 00:18:44.500034 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.512819 | 2025-10-31 00:18:44.512964 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-31 00:18:44.550103 | controller | skipping: Conditional result was False 2025-10-31 00:18:44.576644 | 2025-10-31 00:18:44.576870 | TASK [Disable Fedora Modular] 2025-10-31 00:18:45.341380 | controller | changed 2025-10-31 00:18:45.353609 | 2025-10-31 00:18:45.353787 | TASK [Enable EPEL] 2025-10-31 00:18:45.384331 | controller | skipping: Conditional result was False 2025-10-31 00:18:45.400235 | 2025-10-31 00:18:45.400406 | TASK [Register the RHEL node] 2025-10-31 00:18:45.559220 | 2025-10-31 00:18:45.559483 | TASK [Show the subscription-manager status] 2025-10-31 00:18:45.712797 | controller | skipping: Conditional result was False 2025-10-31 00:18:45.744438 | 2025-10-31 00:18:45.744554 | TASK [Enable EPEL on RHEL] 2025-10-31 00:18:45.895107 | controller | skipping: Conditional result was False 2025-10-31 00:18:45.907259 | 2025-10-31 00:18:45.907396 | TASK [Install git and tox] 2025-10-31 00:20:37.735619 | controller | changed 2025-10-31 00:20:37.748329 | 2025-10-31 00:20:37.748465 | TASK [include_role : prepare-workspace] 2025-10-31 00:20:37.777195 | controller | ok 2025-10-31 00:20:37.813765 | 2025-10-31 00:20:37.813907 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-31 00:20:38.440572 | controller | ok 2025-10-31 00:20:38.456322 | 2025-10-31 00:20:38.456491 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-31 00:20:50.654317 | controller | Output suppressed because no_log was given 2025-10-31 00:20:50.672306 | 2025-10-31 00:20:50.672484 | TASK [include_role : prepare-workspace-openshift] 2025-10-31 00:20:50.702098 | controller | skipping: Conditional result was False 2025-10-31 00:20:50.738381 | 2025-10-31 00:20:50.738546 | PLAY [all:!appliance] 2025-10-31 00:20:50.760669 | 2025-10-31 00:20:50.760873 | TASK [Run add-build-sshkey role (RSA)] 2025-10-31 00:20:50.859285 | controller | ok 2025-10-31 00:20:50.891184 | 2025-10-31 00:20:50.891416 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-31 00:20:51.185757 | controller -> localhost | ok 2025-10-31 00:20:51.195178 | 2025-10-31 00:20:51.195268 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-31 00:20:51.236686 | controller | ok 2025-10-31 00:20:51.264563 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-31 00:20:51.273119 | 2025-10-31 00:20:51.273227 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-31 00:20:51.779447 | controller -> localhost | Generating public/private rsa key pair. 2025-10-31 00:20:51.780014 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_rsa. 2025-10-31 00:20:51.780108 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_rsa.pub. 2025-10-31 00:20:51.780175 | controller -> localhost | The key fingerprint is: 2025-10-31 00:20:51.780285 | controller -> localhost | SHA256:Nz7JMJawcfOmGSlJneThI5tjCMJxRUa4c0PUm5gNSG0 zuul-build-sshkey 2025-10-31 00:20:51.780359 | controller -> localhost | The key's randomart image is: 2025-10-31 00:20:51.780429 | controller -> localhost | +---[RSA 2048]----+ 2025-10-31 00:20:51.780497 | controller -> localhost | | ..oO*. o | 2025-10-31 00:20:51.780566 | controller -> localhost | |. oo.E * o | 2025-10-31 00:20:51.780631 | controller -> localhost | |... + X @ | 2025-10-31 00:20:51.780696 | controller -> localhost | | . + B & * | 2025-10-31 00:20:51.780816 | controller -> localhost | | + X S = | 2025-10-31 00:20:51.780910 | controller -> localhost | | . + @ o | 2025-10-31 00:20:51.781035 | controller -> localhost | | o = | 2025-10-31 00:20:51.781109 | controller -> localhost | | . | 2025-10-31 00:20:51.781176 | controller -> localhost | | | 2025-10-31 00:20:51.781252 | controller -> localhost | +----[SHA256]-----+ 2025-10-31 00:20:51.781406 | controller -> localhost | ok: Runtime: 0:00:00.057504 2025-10-31 00:20:51.801683 | 2025-10-31 00:20:51.801893 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-31 00:20:51.845120 | controller | ok 2025-10-31 00:20:51.866973 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-31 00:20:51.880544 | 2025-10-31 00:20:51.880636 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-31 00:20:51.906102 | controller | skipping: Conditional result was False 2025-10-31 00:20:51.917210 | 2025-10-31 00:20:51.917309 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-31 00:20:52.565106 | controller | changed 2025-10-31 00:20:52.575002 | 2025-10-31 00:20:52.575110 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-31 00:20:52.923788 | controller | ok 2025-10-31 00:20:52.941952 | 2025-10-31 00:20:52.942228 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-31 00:20:54.321556 | controller | changed 2025-10-31 00:20:54.334664 | 2025-10-31 00:20:54.334846 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-31 00:20:55.779542 | controller | changed 2025-10-31 00:20:55.788308 | 2025-10-31 00:20:55.788428 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-31 00:20:55.818098 | controller | skipping: Conditional result was False 2025-10-31 00:20:55.826183 | 2025-10-31 00:20:55.826277 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-31 00:20:56.179245 | controller -> localhost | changed 2025-10-31 00:20:56.191977 | 2025-10-31 00:20:56.192149 | TASK [add-build-sshkey : Add back temp key] 2025-10-31 00:20:56.499498 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_rsa (zuul-build-sshkey) 2025-10-31 00:20:56.500058 | controller -> localhost | ok: Runtime: 0:00:00.008202 2025-10-31 00:20:56.515769 | 2025-10-31 00:20:56.515966 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-31 00:20:57.893050 | controller | ok 2025-10-31 00:20:57.900155 | 2025-10-31 00:20:57.900229 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-31 00:20:57.945754 | controller | skipping: Conditional result was False 2025-10-31 00:20:57.964192 | 2025-10-31 00:20:57.964319 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-31 00:20:58.007310 | controller | ok 2025-10-31 00:20:58.036212 | 2025-10-31 00:20:58.036377 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-31 00:20:58.297964 | controller -> localhost | ok 2025-10-31 00:20:58.304294 | 2025-10-31 00:20:58.304359 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-31 00:20:58.324035 | controller | ok 2025-10-31 00:20:58.334636 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-31 00:20:58.340625 | 2025-10-31 00:20:58.340689 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-31 00:20:58.580776 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-31 00:20:58.580991 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_ecdsa. 2025-10-31 00:20:58.581020 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_ecdsa.pub. 2025-10-31 00:20:58.581064 | controller -> localhost | The key fingerprint is: 2025-10-31 00:20:58.581087 | controller -> localhost | SHA256:LoF/F18DmYY9wr91Y/SD3QdiPYLtDplLBHYnCodxbb4 zuul-build-sshkey 2025-10-31 00:20:58.581106 | controller -> localhost | The key's randomart image is: 2025-10-31 00:20:58.581124 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-31 00:20:58.581141 | controller -> localhost | | oo=.o . | 2025-10-31 00:20:58.581158 | controller -> localhost | | .= =oB + | 2025-10-31 00:20:58.581175 | controller -> localhost | | .o* % +. | 2025-10-31 00:20:58.581192 | controller -> localhost | | . ..O =+oo| 2025-10-31 00:20:58.581208 | controller -> localhost | | . . S *.o.+==| 2025-10-31 00:20:58.581225 | controller -> localhost | | . o .E* +.o+| 2025-10-31 00:20:58.581242 | controller -> localhost | | o o o + | 2025-10-31 00:20:58.581259 | controller -> localhost | | o . | 2025-10-31 00:20:58.581275 | controller -> localhost | | | 2025-10-31 00:20:58.581291 | controller -> localhost | +----[SHA256]-----+ 2025-10-31 00:20:58.581338 | controller -> localhost | ok: Runtime: 0:00:00.008042 2025-10-31 00:20:58.587761 | 2025-10-31 00:20:58.587837 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-31 00:20:58.608490 | controller | ok 2025-10-31 00:20:58.616033 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-31 00:20:58.625020 | 2025-10-31 00:20:58.625101 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-31 00:20:58.639201 | controller | skipping: Conditional result was False 2025-10-31 00:20:58.646065 | 2025-10-31 00:20:58.646143 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-31 00:20:59.122750 | controller | changed 2025-10-31 00:20:59.135396 | 2025-10-31 00:20:59.135545 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-31 00:20:59.504159 | controller | ok 2025-10-31 00:20:59.517151 | 2025-10-31 00:20:59.517327 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-31 00:21:01.109812 | controller | changed 2025-10-31 00:21:01.121561 | 2025-10-31 00:21:01.121698 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-31 00:21:03.871426 | controller | changed 2025-10-31 00:21:03.878973 | 2025-10-31 00:21:03.879059 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-31 00:21:03.903786 | controller | skipping: Conditional result was False 2025-10-31 00:21:03.910120 | 2025-10-31 00:21:03.910196 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-31 00:21:04.169785 | controller -> localhost | changed 2025-10-31 00:21:04.185080 | 2025-10-31 00:21:04.185205 | TASK [add-build-sshkey : Add back temp key] 2025-10-31 00:21:04.479704 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/fa9b7f3af9f242a6a88bb5082ec1036e_id_ecdsa (zuul-build-sshkey) 2025-10-31 00:21:04.480074 | controller -> localhost | ok: Runtime: 0:00:00.008643 2025-10-31 00:21:04.494602 | 2025-10-31 00:21:04.494764 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-31 00:21:04.995978 | controller | ok 2025-10-31 00:21:05.003401 | 2025-10-31 00:21:05.003491 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-31 00:21:05.038670 | controller | skipping: Conditional result was False 2025-10-31 00:21:05.050254 | 2025-10-31 00:21:05.050365 | TASK [include_role : remove-zuul-sshkey] 2025-10-31 00:21:05.073897 | controller | skipping: Conditional result was False 2025-10-31 00:21:05.080431 | 2025-10-31 00:21:05.080516 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-31 00:21:05.463397 | controller | ok: "logs" 2025-10-31 00:21:05.463875 | controller | ok: All items complete 2025-10-31 00:21:05.463945 | 2025-10-31 00:21:05.770795 | controller | ok: "artifacts" 2025-10-31 00:21:06.058955 | controller | ok: "docs" 2025-10-31 00:21:06.074268 | 2025-10-31 00:21:06.074364 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-31 00:21:06.421947 | controller | changed: "logs" 2025-10-31 00:21:06.746189 | controller | changed: "artifacts" 2025-10-31 00:21:07.057893 | controller | changed: "docs" 2025-10-31 00:21:07.111654 | 2025-10-31 00:21:07.111789 | PLAY RECAP 2025-10-31 00:21:07.111845 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-31 00:21:07.111879 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-31 00:21:07.111903 | 2025-10-31 00:21:07.229600 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-31 00:21:07.230623 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-31 00:21:07.800419 | 2025-10-31 00:21:07.800564 | PLAY [all] 2025-10-31 00:21:07.822403 | 2025-10-31 00:21:07.822545 | TASK [Install binary dependencies] 2025-10-31 00:21:07.891870 | controller | ok 2025-10-31 00:21:07.910631 | 2025-10-31 00:21:07.910751 | TASK [bindep : Include find tasks] 2025-10-31 00:21:07.949125 | controller | ok 2025-10-31 00:21:07.956527 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-31 00:21:07.962406 | 2025-10-31 00:21:07.962467 | TASK [bindep : Look for bindep.txt] 2025-10-31 00:21:08.515708 | controller | ok 2025-10-31 00:21:08.528774 | 2025-10-31 00:21:08.528923 | TASK [bindep : Define bindep_file fact] 2025-10-31 00:21:08.556106 | controller | skipping: Conditional result was False 2025-10-31 00:21:08.569667 | 2025-10-31 00:21:08.569842 | TASK [bindep : Look for other-requirements.txt] 2025-10-31 00:21:08.914328 | controller | ok 2025-10-31 00:21:08.926162 | 2025-10-31 00:21:08.926308 | TASK [bindep : Define bindep_file fact] 2025-10-31 00:21:08.964012 | controller | skipping: Conditional result was False 2025-10-31 00:21:08.976876 | 2025-10-31 00:21:08.977071 | TASK [bindep : Look for bindep fallback file] 2025-10-31 00:21:09.014448 | controller | skipping: Conditional result was False 2025-10-31 00:21:09.027413 | 2025-10-31 00:21:09.027571 | TASK [bindep : Define bindep_file fact] 2025-10-31 00:21:09.064869 | controller | skipping: Conditional result was False 2025-10-31 00:21:09.078013 | 2025-10-31 00:21:09.078190 | TASK [bindep : Include bindep tasks] 2025-10-31 00:21:09.104232 | controller | skipping: Conditional result was False 2025-10-31 00:21:09.120054 | 2025-10-31 00:21:09.120189 | TASK [bindep : Include install tasks] 2025-10-31 00:21:09.146792 | controller | skipping: Conditional result was False 2025-10-31 00:21:09.159558 | 2025-10-31 00:21:09.159696 | LOOP [bindep : Include package tasks] 2025-10-31 00:21:09.228018 | 2025-10-31 00:21:09.228421 | TASK [Run test-setup role] 2025-10-31 00:21:09.254402 | controller | ok 2025-10-31 00:21:09.283643 | 2025-10-31 00:21:09.283770 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-31 00:21:09.655578 | controller | ok 2025-10-31 00:21:09.669068 | 2025-10-31 00:21:09.669202 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-31 00:21:09.816039 | controller | skipping: Conditional result was False 2025-10-31 00:21:09.864383 | 2025-10-31 00:21:09.864490 | PLAY RECAP 2025-10-31 00:21:09.864543 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-31 00:21:09.864570 | 2025-10-31 00:21:09.959840 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-31 00:21:09.961446 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-31 00:21:10.567596 | 2025-10-31 00:21:10.567759 | PLAY [controller] 2025-10-31 00:21:10.587284 | 2025-10-31 00:21:10.587378 | TASK [Create the /root directory] 2025-10-31 00:21:11.380194 | controller | ok 2025-10-31 00:21:11.393465 | 2025-10-31 00:21:11.393623 | TASK [Install glibc-langpack-en] 2025-10-31 00:21:19.467786 | controller | ok: Nothing to do 2025-10-31 00:21:19.481280 | 2025-10-31 00:21:19.481498 | TASK [Ensure controller directory exists] 2025-10-31 00:21:19.973773 | controller | changed 2025-10-31 00:21:19.986484 | 2025-10-31 00:21:19.986918 | TASK [Install container runtime] 2025-10-31 00:21:20.067659 | controller | ok 2025-10-31 00:21:20.125906 | 2025-10-31 00:21:20.126048 | LOOP [ensure-podman : Find distribution installation] 2025-10-31 00:21:20.169823 | controller | ok: "/var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-31 00:21:20.177998 | controller | included: /var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-31 00:21:20.184191 | 2025-10-31 00:21:20.184256 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-31 00:22:43.982945 | controller | changed 2025-10-31 00:22:43.997485 | 2025-10-31 00:22:43.997640 | TASK [ensure-podman : Fetch podman version] 2025-10-31 00:22:44.723038 | controller | Client: Podman Engine 2025-10-31 00:22:44.750736 | controller | Version: 4.6.2 2025-10-31 00:22:44.750775 | controller | API Version: 4.6.2 2025-10-31 00:22:44.750782 | controller | Go Version: go1.19.12 2025-10-31 00:22:44.750801 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-31 00:22:44.750810 | controller | OS/Arch: linux/amd64 2025-10-31 00:22:45.135301 | controller | ok: Runtime: 0:00:00.226945 2025-10-31 00:22:45.143998 | 2025-10-31 00:22:45.144103 | TASK [ensure-podman : Print podman version installed] 2025-10-31 00:22:45.177484 | Podman version: Client: Podman Engine 2025-10-31 00:22:45.177680 | Version: 4.6.2 2025-10-31 00:22:45.177720 | API Version: 4.6.2 2025-10-31 00:22:45.177777 | Go Version: go1.19.12 2025-10-31 00:22:45.177803 | Built: Mon Aug 28 19:38:31 2023 2025-10-31 00:22:45.177832 | OS/Arch: linux/amd64 2025-10-31 00:22:45.185703 | 2025-10-31 00:22:45.185805 | TASK [ensure-podman : Validate podman engine] 2025-10-31 00:22:45.323395 | controller | skipping: Conditional result was False 2025-10-31 00:22:45.337178 | 2025-10-31 00:22:45.337337 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-31 00:22:45.365029 | controller | skipping: Conditional result was False 2025-10-31 00:22:45.390861 | 2025-10-31 00:22:45.391051 | TASK [Ensure python3.8 is present] 2025-10-31 00:22:45.418982 | controller | skipping: Conditional result was False 2025-10-31 00:22:45.427340 | 2025-10-31 00:22:45.427426 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-31 00:22:45.451865 | controller | ok 2025-10-31 00:22:45.479625 | 2025-10-31 00:22:45.479742 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-31 00:22:49.262078 | controller | ok: Nothing to do 2025-10-31 00:22:49.274658 | 2025-10-31 00:22:49.274835 | TASK [our-ensure-python : Also install python3-devel] 2025-10-31 00:23:05.704549 | controller | changed 2025-10-31 00:23:05.714879 | 2025-10-31 00:23:05.714947 | TASK [Run ensure-virtualenv role] 2025-10-31 00:23:05.734451 | controller | ok 2025-10-31 00:23:05.754932 | 2025-10-31 00:23:05.755040 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-31 00:23:06.208044 | controller | /usr/bin/virtualenv 2025-10-31 00:23:06.388990 | controller | ok: Runtime: 0:00:00.004918 2025-10-31 00:23:06.398534 | 2025-10-31 00:23:06.398632 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-31 00:23:06.425970 | controller | skipping: Conditional result was False 2025-10-31 00:23:06.426227 | controller | ok: All items complete 2025-10-31 00:23:06.426256 | 2025-10-31 00:23:06.447677 | 2025-10-31 00:23:06.447846 | TASK [Find the full path of the Python interpreter] 2025-10-31 00:23:06.931178 | controller | /usr/bin/python3 2025-10-31 00:23:07.115821 | controller | ok 2025-10-31 00:23:07.127178 | 2025-10-31 00:23:07.127314 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-31 00:23:08.670247 | controller | created virtual environment CPython3.11.0.final.0-64 in 825ms 2025-10-31 00:23:08.713325 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-31 00:23:08.713383 | 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-31 00:23:08.713401 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-31 00:23:08.713425 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-31 00:23:08.810370 | controller | changed 2025-10-31 00:23:08.822337 | 2025-10-31 00:23:08.822508 | TASK [Set selinux package] 2025-10-31 00:23:08.861151 | controller | ok 2025-10-31 00:23:08.871881 | 2025-10-31 00:23:08.872032 | TASK [Set selinux package (Fedora)] 2025-10-31 00:23:08.930052 | controller | ok 2025-10-31 00:23:08.940566 | 2025-10-31 00:23:08.940752 | TASK [Install selinux into virtualenv] 2025-10-31 00:23:11.629462 | controller | Collecting selinux-please-lie-to-me 2025-10-31 00:23:11.718751 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-31 00:23:12.250472 | controller | Collecting setuptools<50.0.0 2025-10-31 00:23:12.264373 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-31 00:23:12.402132 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.2 MB/s eta 0:00:00 2025-10-31 00:23:12.555921 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-31 00:23:12.556235 | controller | Attempting uninstall: setuptools 2025-10-31 00:23:12.561155 | controller | Found existing installation: setuptools 62.6.0 2025-10-31 00:23:12.674094 | controller | Uninstalling setuptools-62.6.0: 2025-10-31 00:23:12.689390 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-31 00:23:13.443015 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-31 00:23:13.649965 | controller | 2025-10-31 00:23:13.866781 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-31 00:23:13.866826 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-31 00:23:14.157920 | controller | ok: Runtime: 0:00:04.429883 2025-10-31 00:23:14.169952 | 2025-10-31 00:23:14.170108 | TASK [Install pytest-forked into virtualenv] 2025-10-31 00:23:15.413256 | controller | Collecting pytest-forked 2025-10-31 00:23:15.506128 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-31 00:23:15.567292 | controller | Collecting py 2025-10-31 00:23:15.582236 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-31 00:23:15.619976 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-10-31 00:23:15.807453 | controller | Collecting pytest>=3.10 2025-10-31 00:23:15.822370 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-31 00:23:15.900731 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 4.8 MB/s eta 0:00:00 2025-10-31 00:23:16.040872 | controller | Collecting iniconfig>=1 2025-10-31 00:23:16.058350 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-31 00:23:16.174518 | controller | Collecting packaging>=20 2025-10-31 00:23:16.189198 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-31 00:23:16.204197 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.4 MB/s eta 0:00:00 2025-10-31 00:23:16.253049 | controller | Collecting pluggy<2,>=1.5 2025-10-31 00:23:16.267889 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-31 00:23:16.361409 | controller | Collecting pygments>=2.7.2 2025-10-31 00:23:16.375998 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-31 00:23:16.516332 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.0 MB/s eta 0:00:00 2025-10-31 00:23:16.670049 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-31 00:23:19.119601 | 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-10-31 00:23:19.136240 | controller | 2025-10-31 00:23:19.329439 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-31 00:23:19.329486 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-31 00:23:19.400863 | controller | ok: Runtime: 0:00:04.659568 2025-10-31 00:23:19.413191 | 2025-10-31 00:23:19.413348 | TASK [Update pip] 2025-10-31 00:23:20.544680 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-31 00:23:20.828528 | controller | Collecting pip 2025-10-31 00:23:20.932595 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-10-31 00:23:21.027068 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.9 MB/s eta 0:00:00 2025-10-31 00:23:21.189277 | controller | Installing collected packages: pip 2025-10-31 00:23:21.189734 | controller | Attempting uninstall: pip 2025-10-31 00:23:21.194293 | controller | Found existing installation: pip 22.2.2 2025-10-31 00:23:21.456043 | controller | Uninstalling pip-22.2.2: 2025-10-31 00:23:21.486180 | controller | Successfully uninstalled pip-22.2.2 2025-10-31 00:23:23.339825 | controller | Successfully installed pip-25.3 2025-10-31 00:23:24.079237 | controller | ok: Runtime: 0:00:03.624692 2025-10-31 00:23:24.091053 | 2025-10-31 00:23:24.091310 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-31 00:23:24.658315 | controller | changed 2025-10-31 00:23:24.669702 | 2025-10-31 00:23:24.669864 | TASK [Install ansible into virtualenv] 2025-10-31 00:23:25.757201 | controller | Processing ./src/github.com/ansible/ansible 2025-10-31 00:23:25.763877 | controller | Installing build dependencies: started 2025-10-31 00:23:27.811690 | controller | Installing build dependencies: finished with status 'done' 2025-10-31 00:23:29.350217 | controller | Getting requirements to build wheel: started 2025-10-31 00:23:29.350280 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-31 00:23:30.296697 | controller | Preparing metadata (pyproject.toml): started 2025-10-31 00:23:30.296753 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-31 00:23:30.299883 | 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-31 00:23:30.304863 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-31 00:23:30.836174 | controller | ERROR 2025-10-31 00:23:30.836533 | controller | { 2025-10-31 00:23:30.836597 | controller | "delta": "0:00:05.276678", 2025-10-31 00:23:30.836639 | controller | "end": "2025-10-31 00:23:30.456444", 2025-10-31 00:23:30.836676 | controller | "msg": "non-zero return code", 2025-10-31 00:23:30.836763 | controller | "rc": 1, 2025-10-31 00:23:30.836812 | controller | "start": "2025-10-31 00:23:25.179766" 2025-10-31 00:23:30.836848 | controller | } failure 2025-10-31 00:23:30.840049 | 2025-10-31 00:23:30.840155 | PLAY RECAP 2025-10-31 00:23:30.840233 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-31 00:23:30.840276 | 2025-10-31 00:23:30.968189 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-31 00:23:30.969145 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-31 00:23:31.570006 | 2025-10-31 00:23:31.570127 | PLAY [all] 2025-10-31 00:23:31.590816 | 2025-10-31 00:23:31.590911 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-31 00:23:32.439903 | controller | changed: non-zero return code 2025-10-31 00:23:32.451906 | 2025-10-31 00:23:32.452086 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-31 00:23:32.479120 | controller | skipping: Conditional result was False 2025-10-31 00:23:32.491082 | 2025-10-31 00:23:32.491245 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-31 00:23:32.531173 | 2025-10-31 00:23:32.531442 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-31 00:23:32.570456 | 2025-10-31 00:23:32.570774 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-31 00:23:32.597893 | controller | skipping: Conditional result was False 2025-10-31 00:23:32.611802 | 2025-10-31 00:23:32.611973 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-31 00:23:32.653325 | 2025-10-31 00:23:32.653601 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-31 00:23:32.670897 | controller | skipping: Conditional result was False 2025-10-31 00:23:32.679841 | 2025-10-31 00:23:32.679940 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-31 00:23:32.694913 | controller | skipping: Conditional result was False 2025-10-31 00:23:32.704750 | 2025-10-31 00:23:32.704869 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-31 00:23:32.729826 | controller | skipping: Conditional result was False 2025-10-31 00:23:32.764339 | 2025-10-31 00:23:32.764449 | PLAY RECAP 2025-10-31 00:23:32.764501 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-31 00:23:32.764528 | 2025-10-31 00:23:32.850992 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-31 00:23:32.851817 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-31 00:23:33.405815 | 2025-10-31 00:23:33.405935 | PLAY [all:!appliance*] 2025-10-31 00:23:33.427103 | 2025-10-31 00:23:33.427188 | TASK [unregister the node] 2025-10-31 00:23:33.553450 | controller | skipping: Conditional result was False 2025-10-31 00:23:33.566265 | 2025-10-31 00:23:33.566421 | TASK [include_role : fetch-output] 2025-10-31 00:23:33.612426 | controller | ok 2025-10-31 00:23:33.633465 | 2025-10-31 00:23:33.633575 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-31 00:23:33.709364 | controller | skipping: Conditional result was False 2025-10-31 00:23:33.715568 | 2025-10-31 00:23:33.715647 | TASK [fetch-output : Set log path for single node] 2025-10-31 00:23:33.754976 | controller | ok 2025-10-31 00:23:33.760047 | 2025-10-31 00:23:33.760110 | LOOP [fetch-output : Ensure local output dirs] 2025-10-31 00:23:34.217943 | controller -> localhost | ok: "/var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/logs" 2025-10-31 00:23:34.483171 | controller -> localhost | changed: "/var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/artifacts" 2025-10-31 00:23:34.734360 | controller -> localhost | changed: "/var/lib/zuul/builds/fa9b7f3af9f242a6a88bb5082ec1036e/work/docs" 2025-10-31 00:23:34.747622 | 2025-10-31 00:23:34.747702 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-31 00:23:36.008141 | controller | changed: 2025-10-31 00:23:36.008540 | controller | .d..t...... ./ 2025-10-31 00:23:36.008604 | controller | cd+++++++++ controller/ 2025-10-31 00:23:36.008671 | controller | changed: All items complete 2025-10-31 00:23:36.008714 | 2025-10-31 00:23:37.118940 | controller | changed: .d..t...... ./ 2025-10-31 00:23:38.271806 | controller | changed: .d..t...... ./ 2025-10-31 00:23:38.308617 | 2025-10-31 00:23:38.308886 | TASK [include_role : fetch-output-openshift] 2025-10-31 00:23:38.334642 | controller | skipping: Conditional result was False 2025-10-31 00:23:38.344653 | 2025-10-31 00:23:38.344786 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-31 00:23:38.393522 | controller | skipping: Conditional result was False 2025-10-31 00:23:38.408193 | controller | skipping: Conditional result was False 2025-10-31 00:23:38.455110 | 2025-10-31 00:23:38.455266 | PLAY [localhost] 2025-10-31 00:23:38.474499 | 2025-10-31 00:23:38.474599 | TASK [Run Zuul manifest role] 2025-10-31 00:23:38.498596 | localhost | ok 2025-10-31 00:23:38.518957 | 2025-10-31 00:23:38.519038 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-31 00:23:38.975806 | localhost | changed 2025-10-31 00:23:38.980501 | 2025-10-31 00:23:38.980561 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-31 00:23:39.033108 | localhost | ok 2025-10-31 00:23:39.041445 | 2025-10-31 00:23:39.041505 | TASK [Set zuul-log-path fact] 2025-10-31 00:23:39.072384 | localhost | ok 2025-10-31 00:23:39.091543 | 2025-10-31 00:23:39.091633 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-31 00:23:39.134690 | localhost | ok 2025-10-31 00:23:39.148886 | 2025-10-31 00:23:39.148970 | LOOP [Run upload-logs-swift role] 2025-10-31 00:23:39.205430 | localhost | Output suppressed because no_log was given 2025-10-31 00:23:39.230888 | 2025-10-31 00:23:39.230963 | TASK [Set zuul-log-path fact] 2025-10-31 00:23:39.275816 | localhost | skipping: Conditional result was False 2025-10-31 00:23:39.280972 | 2025-10-31 00:23:39.281035 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-31 00:23:39.783138 | localhost -> localhost | ok: Runtime: 0:00:00.017500 2025-10-31 00:23:39.792498 | 2025-10-31 00:23:39.792583 | TASK [upload-logs-swift : Upload logs to swift]