2025-10-09 00:07:01.436264 | Job console starting...
2025-10-09 00:07:01.451556 | Updating repositories
2025-10-09 00:07:04.196223 | Preparing job workspace
2025-10-09 00:07:08.289967 | Running Ansible setup...
2025-10-09 00:07:14.622200 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-09 00:07:15.273945 | 
2025-10-09 00:07:15.274075 | PLAY [localhost]
2025-10-09 00:07:15.283122 | 
2025-10-09 00:07:15.283219 | TASK [Gathering Facts]
2025-10-09 00:07:16.257445 | localhost | ok
2025-10-09 00:07:16.272343 | 
2025-10-09 00:07:16.272484 | TASK [Setup log path fact]
2025-10-09 00:07:16.290079 | localhost | ok
2025-10-09 00:07:16.303584 | 
2025-10-09 00:07:16.303729 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-09 00:07:16.332747 | localhost | ok
2025-10-09 00:07:16.341373 | 
2025-10-09 00:07:16.341495 | TASK [emit-job-header : Print job information]
2025-10-09 00:07:16.369863 | # Job Information
2025-10-09 00:07:16.370023 | Ansible Version: 2.15.12
2025-10-09 00:07:16.370059 | Job: ansible-test-sanity-docker-devel
2025-10-09 00:07:16.370081 | Pipeline: periodic
2025-10-09 00:07:16.370101 | Executor: ze04.softwarefactory-project.io
2025-10-09 00:07:16.370120 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-09 00:07:16.370142 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/07a/ansible/07a6aad27d5c45978cf43567add33200/
2025-10-09 00:07:16.370162 | Event ID: 7e5f5b9352a645a081c4b0c8a3c28952
2025-10-09 00:07:16.374108 | 
2025-10-09 00:07:16.374176 | LOOP [emit-job-header : Print node information]
2025-10-09 00:07:16.484876 | localhost | ok:
2025-10-09 00:07:16.485120 | localhost | # Node Information
2025-10-09 00:07:16.485155 | localhost | Inventory Hostname: controller
2025-10-09 00:07:16.485280 | localhost | Hostname: ip-172-16-125-128
2025-10-09 00:07:16.485312 | localhost | Username: zuul-worker
2025-10-09 00:07:16.485342 | localhost | Distro: Fedora 37
2025-10-09 00:07:16.485368 | localhost | Provider: ansible-us-east-2
2025-10-09 00:07:16.485391 | localhost | Region: us-east-2
2025-10-09 00:07:16.485414 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-09 00:07:16.485461 | localhost | Product Name: t3.small
2025-10-09 00:07:16.485485 | localhost | Interface IP: 18.191.133.144
2025-10-09 00:07:16.512063 | 
2025-10-09 00:07:16.512254 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-09 00:07:16.947269 | localhost -> localhost | changed
2025-10-09 00:07:16.954709 | 
2025-10-09 00:07:16.954811 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-09 00:07:17.855648 | localhost -> localhost | changed
2025-10-09 00:07:17.889191 | 
2025-10-09 00:07:17.889289 | PLAY [all:!appliance*]
2025-10-09 00:07:17.910451 | 
2025-10-09 00:07:17.910561 | TASK [include_role : start-zuul-console]
2025-10-09 00:07:17.944380 | controller | ok
2025-10-09 00:07:17.968424 | 
2025-10-09 00:07:17.969284 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-09 00:07:18.714443 | controller | ok
2025-10-09 00:07:18.734710 | 
2025-10-09 00:07:18.734816 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-09 00:07:20.818876 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-09 00:07:20.826139 | 
2025-10-09 00:07:20.826233 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-09 00:07:20.972288 | controller | skipping: Conditional result was False
2025-10-09 00:07:20.978298 | 
2025-10-09 00:07:20.978390 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-09 00:07:21.003470 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.009642 | 
2025-10-09 00:07:21.009752 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-09 00:07:21.034829 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.041235 | 
2025-10-09 00:07:21.041340 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-09 00:07:21.066102 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.072625 | 
2025-10-09 00:07:21.072842 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-09 00:07:21.096756 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.103093 | 
2025-10-09 00:07:21.103308 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-09 00:07:21.127307 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.140467 | 
2025-10-09 00:07:21.140578 | TASK [Disable Fedora Modular]
2025-10-09 00:07:21.897532 | controller | changed
2025-10-09 00:07:21.915283 | 
2025-10-09 00:07:21.915460 | TASK [Enable EPEL]
2025-10-09 00:07:21.931812 | controller | skipping: Conditional result was False
2025-10-09 00:07:21.941764 | 
2025-10-09 00:07:21.941901 | TASK [Register the RHEL node]
2025-10-09 00:07:22.111328 | 
2025-10-09 00:07:22.111624 | TASK [Show the subscription-manager status]
2025-10-09 00:07:22.306254 | controller | skipping: Conditional result was False
2025-10-09 00:07:22.322530 | 
2025-10-09 00:07:22.322789 | TASK [Enable EPEL on RHEL]
2025-10-09 00:07:22.509839 | controller | skipping: Conditional result was False
2025-10-09 00:07:22.519259 | 
2025-10-09 00:07:22.519401 | TASK [Install git and tox]
2025-10-09 00:08:50.709079 | controller | changed
2025-10-09 00:08:50.726543 | 
2025-10-09 00:08:50.726841 | TASK [include_role : prepare-workspace]
2025-10-09 00:08:50.756555 | controller | ok
2025-10-09 00:08:50.797862 | 
2025-10-09 00:08:50.798017 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-09 00:08:51.296482 | controller | ok
2025-10-09 00:08:51.312144 | 
2025-10-09 00:08:51.312321 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-09 00:09:10.289467 | controller | Output suppressed because no_log was given
2025-10-09 00:09:10.302246 | 
2025-10-09 00:09:10.302387 | TASK [include_role : prepare-workspace-openshift]
2025-10-09 00:09:10.319505 | controller | skipping: Conditional result was False
2025-10-09 00:09:10.379446 | 
2025-10-09 00:09:10.379543 | PLAY [all:!appliance]
2025-10-09 00:09:10.397421 | 
2025-10-09 00:09:10.397548 | TASK [Run add-build-sshkey role (RSA)]
2025-10-09 00:09:10.418861 | controller | ok
2025-10-09 00:09:10.436439 | 
2025-10-09 00:09:10.436558 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-09 00:09:10.673272 | controller -> localhost | ok
2025-10-09 00:09:10.683032 | 
2025-10-09 00:09:10.683163 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-09 00:09:10.710327 | controller | ok
2025-10-09 00:09:10.726653 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-09 00:09:10.734041 | 
2025-10-09 00:09:10.734163 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-09 00:09:11.252142 | controller -> localhost | Generating public/private rsa key pair.
2025-10-09 00:09:11.252381 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_rsa.
2025-10-09 00:09:11.252436 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_rsa.pub.
2025-10-09 00:09:11.252488 | controller -> localhost | The key fingerprint is:
2025-10-09 00:09:11.252517 | controller -> localhost | SHA256:nD6Vsxi8R/p6T1pwCXbb4XNXwDDbwI8wGy9OMrKJmRI zuul-build-sshkey
2025-10-09 00:09:11.252547 | controller -> localhost | The key's randomart image is:
2025-10-09 00:09:11.252574 | controller -> localhost | +---[RSA 2048]----+
2025-10-09 00:09:11.252600 | controller -> localhost | |           .+o.  |
2025-10-09 00:09:11.252655 | controller -> localhost | |          + .=.. |
2025-10-09 00:09:11.253247 | controller -> localhost | |          o*ooo .|
2025-10-09 00:09:11.253307 | controller -> localhost | |  E   .ooo++o=...|
2025-10-09 00:09:11.253339 | controller -> localhost | |   . + +S=*.+ + o|
2025-10-09 00:09:11.253380 | controller -> localhost | |  . + o. B.=   o.|
2025-10-09 00:09:11.253410 | controller -> localhost | |   .    * o o    |
2025-10-09 00:09:11.253452 | controller -> localhost | |         +.+     |
2025-10-09 00:09:11.253487 | controller -> localhost | |        .oo..    |
2025-10-09 00:09:11.253517 | controller -> localhost | +----[SHA256]-----+
2025-10-09 00:09:11.253581 | controller -> localhost | ok: Runtime: 0:00:00.091194
2025-10-09 00:09:11.263827 | 
2025-10-09 00:09:11.263954 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-09 00:09:11.297214 | controller | ok
2025-10-09 00:09:11.308960 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-09 00:09:11.319806 | 
2025-10-09 00:09:11.319922 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-09 00:09:11.345881 | controller | skipping: Conditional result was False
2025-10-09 00:09:11.357024 | 
2025-10-09 00:09:11.357207 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-09 00:09:12.050047 | controller | changed
2025-10-09 00:09:12.058134 | 
2025-10-09 00:09:12.058255 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-09 00:09:12.422055 | controller | ok
2025-10-09 00:09:12.430580 | 
2025-10-09 00:09:12.430672 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-09 00:09:13.736222 | controller | changed
2025-10-09 00:09:13.748095 | 
2025-10-09 00:09:13.748233 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-09 00:09:15.016395 | controller | changed
2025-10-09 00:09:15.031000 | 
2025-10-09 00:09:15.031166 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-09 00:09:15.058935 | controller | skipping: Conditional result was False
2025-10-09 00:09:15.067745 | 
2025-10-09 00:09:15.067869 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-09 00:09:15.505668 | controller -> localhost | changed
2025-10-09 00:09:15.532162 | 
2025-10-09 00:09:15.532357 | TASK [add-build-sshkey : Add back temp key]
2025-10-09 00:09:15.857576 | controller -> localhost | Identity added: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_rsa (zuul-build-sshkey)
2025-10-09 00:09:15.857851 | controller -> localhost | ok: Runtime: 0:00:00.008119
2025-10-09 00:09:15.864579 | 
2025-10-09 00:09:15.864646 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-09 00:09:16.412599 | controller | ok
2025-10-09 00:09:16.420313 | 
2025-10-09 00:09:16.420404 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-09 00:09:16.445238 | controller | skipping: Conditional result was False
2025-10-09 00:09:16.460650 | 
2025-10-09 00:09:16.460891 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-09 00:09:16.486117 | controller | ok
2025-10-09 00:09:16.504855 | 
2025-10-09 00:09:16.504969 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-09 00:09:16.754001 | controller -> localhost | ok
2025-10-09 00:09:16.764089 | 
2025-10-09 00:09:16.764239 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-09 00:09:16.806588 | controller | ok
2025-10-09 00:09:16.821259 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-09 00:09:16.829305 | 
2025-10-09 00:09:16.829434 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-09 00:09:17.108303 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-09 00:09:17.108555 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_ecdsa.
2025-10-09 00:09:17.108594 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_ecdsa.pub.
2025-10-09 00:09:17.108631 | controller -> localhost | The key fingerprint is:
2025-10-09 00:09:17.108658 | controller -> localhost | SHA256:Fj/Ygqopl345lxtOoU/6B5YvSPuov0FZgQsxZR/ytwA zuul-build-sshkey
2025-10-09 00:09:17.108709 | controller -> localhost | The key's randomart image is:
2025-10-09 00:09:17.108741 | controller -> localhost | +---[ECDSA 521]---+
2025-10-09 00:09:17.108768 | controller -> localhost | |  ooE.o          |
2025-10-09 00:09:17.108794 | controller -> localhost | |  .o.= o         |
2025-10-09 00:09:17.108816 | controller -> localhost | |   . .= o        |
2025-10-09 00:09:17.108838 | controller -> localhost | |    .o + *       |
2025-10-09 00:09:17.108864 | controller -> localhost | |    o o.S +      |
2025-10-09 00:09:17.108887 | controller -> localhost | |   ..o+o . .     |
2025-10-09 00:09:17.108909 | controller -> localhost | |   o+=++         |
2025-10-09 00:09:17.108932 | controller -> localhost | |. oo*O+.o        |
2025-10-09 00:09:17.108957 | controller -> localhost | | +=+=**+         |
2025-10-09 00:09:17.108980 | controller -> localhost | +----[SHA256]-----+
2025-10-09 00:09:17.109040 | controller -> localhost | ok: Runtime: 0:00:00.007670
2025-10-09 00:09:17.117331 | 
2025-10-09 00:09:17.117434 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-09 00:09:17.148951 | controller | ok
2025-10-09 00:09:17.157269 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-09 00:09:17.168566 | 
2025-10-09 00:09:17.168794 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-09 00:09:17.194060 | controller | skipping: Conditional result was False
2025-10-09 00:09:17.206053 | 
2025-10-09 00:09:17.206204 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-09 00:09:17.659107 | controller | changed
2025-10-09 00:09:17.666225 | 
2025-10-09 00:09:17.666306 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-09 00:09:17.994506 | controller | ok
2025-10-09 00:09:18.001061 | 
2025-10-09 00:09:18.001138 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-09 00:09:19.302788 | controller | changed
2025-10-09 00:09:19.310880 | 
2025-10-09 00:09:19.310996 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-09 00:09:20.588643 | controller | changed
2025-10-09 00:09:20.604817 | 
2025-10-09 00:09:20.604969 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-09 00:09:20.631408 | controller | skipping: Conditional result was False
2025-10-09 00:09:20.642152 | 
2025-10-09 00:09:20.642283 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-09 00:09:20.945270 | controller -> localhost | changed
2025-10-09 00:09:20.962775 | 
2025-10-09 00:09:20.962915 | TASK [add-build-sshkey : Add back temp key]
2025-10-09 00:09:21.236099 | controller -> localhost | Identity added: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/07a6aad27d5c45978cf43567add33200_id_ecdsa (zuul-build-sshkey)
2025-10-09 00:09:21.236313 | controller -> localhost | ok: Runtime: 0:00:00.007277
2025-10-09 00:09:21.243143 | 
2025-10-09 00:09:21.243324 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-09 00:09:21.581422 | controller | ok
2025-10-09 00:09:21.622922 | 
2025-10-09 00:09:21.623053 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-09 00:09:21.647743 | controller | skipping: Conditional result was False
2025-10-09 00:09:21.659345 | 
2025-10-09 00:09:21.659430 | TASK [include_role : remove-zuul-sshkey]
2025-10-09 00:09:21.674255 | controller | skipping: Conditional result was False
2025-10-09 00:09:21.682713 | 
2025-10-09 00:09:21.682829 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-09 00:09:22.011993 | controller | ok: "logs"
2025-10-09 00:09:22.012350 | controller | ok: All items complete
2025-10-09 00:09:22.012402 | 
2025-10-09 00:09:22.286614 | controller | ok: "artifacts"
2025-10-09 00:09:22.576652 | controller | ok: "docs"
2025-10-09 00:09:22.595445 | 
2025-10-09 00:09:22.595595 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-09 00:09:22.914035 | controller | changed: "logs"
2025-10-09 00:09:23.214367 | controller | changed: "artifacts"
2025-10-09 00:09:23.483985 | controller | changed: "docs"
2025-10-09 00:09:23.510710 | 
2025-10-09 00:09:23.510811 | PLAY RECAP
2025-10-09 00:09:23.510868 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-09 00:09:23.510897 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-09 00:09:23.510920 | 
2025-10-09 00:09:23.651294 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-09 00:09:23.652232 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-09 00:09:24.264206 | 
2025-10-09 00:09:24.264312 | PLAY [all]
2025-10-09 00:09:24.290319 | 
2025-10-09 00:09:24.290474 | TASK [Install binary dependencies]
2025-10-09 00:09:24.343122 | controller | ok
2025-10-09 00:09:24.366825 | 
2025-10-09 00:09:24.366954 | TASK [bindep : Include find tasks]
2025-10-09 00:09:24.397421 | controller | ok
2025-10-09 00:09:24.412212 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-09 00:09:24.419296 | 
2025-10-09 00:09:24.419389 | TASK [bindep : Look for bindep.txt]
2025-10-09 00:09:24.938228 | controller | ok
2025-10-09 00:09:24.953924 | 
2025-10-09 00:09:24.954113 | TASK [bindep : Define bindep_file fact]
2025-10-09 00:09:24.982484 | controller | skipping: Conditional result was False
2025-10-09 00:09:24.990904 | 
2025-10-09 00:09:24.991039 | TASK [bindep : Look for other-requirements.txt]
2025-10-09 00:09:25.311173 | controller | ok
2025-10-09 00:09:25.318230 | 
2025-10-09 00:09:25.318328 | TASK [bindep : Define bindep_file fact]
2025-10-09 00:09:25.343337 | controller | skipping: Conditional result was False
2025-10-09 00:09:25.351653 | 
2025-10-09 00:09:25.351825 | TASK [bindep : Look for bindep fallback file]
2025-10-09 00:09:25.376647 | controller | skipping: Conditional result was False
2025-10-09 00:09:25.383069 | 
2025-10-09 00:09:25.383200 | TASK [bindep : Define bindep_file fact]
2025-10-09 00:09:25.407415 | controller | skipping: Conditional result was False
2025-10-09 00:09:25.413436 | 
2025-10-09 00:09:25.413510 | TASK [bindep : Include bindep tasks]
2025-10-09 00:09:25.437252 | controller | skipping: Conditional result was False
2025-10-09 00:09:25.446374 | 
2025-10-09 00:09:25.446471 | TASK [bindep : Include install tasks]
2025-10-09 00:09:25.470775 | controller | skipping: Conditional result was False
2025-10-09 00:09:25.478669 | 
2025-10-09 00:09:25.478815 | LOOP [bindep : Include package tasks]
2025-10-09 00:09:25.552367 | 
2025-10-09 00:09:25.552539 | TASK [Run test-setup role]
2025-10-09 00:09:25.582557 | controller | ok
2025-10-09 00:09:25.633238 | 
2025-10-09 00:09:25.633351 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-09 00:09:25.939420 | controller | ok
2025-10-09 00:09:25.953165 | 
2025-10-09 00:09:25.953293 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-09 00:09:26.111639 | controller | skipping: Conditional result was False
2025-10-09 00:09:26.156550 | 
2025-10-09 00:09:26.156674 | PLAY RECAP
2025-10-09 00:09:26.156759 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-09 00:09:26.156789 | 
2025-10-09 00:09:26.261748 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-09 00:09:26.262915 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-09 00:09:26.922430 | 
2025-10-09 00:09:26.922571 | PLAY [controller]
2025-10-09 00:09:26.944570 | 
2025-10-09 00:09:26.944710 | TASK [Create the /root directory]
2025-10-09 00:09:27.692056 | controller | ok
2025-10-09 00:09:27.710225 | 
2025-10-09 00:09:27.710405 | TASK [Install glibc-langpack-en]
2025-10-09 00:09:35.814760 | controller | ok: Nothing to do
2025-10-09 00:09:35.823713 | 
2025-10-09 00:09:35.823845 | TASK [Ensure controller directory exists]
2025-10-09 00:09:36.290264 | controller | changed
2025-10-09 00:09:36.298622 | 
2025-10-09 00:09:36.298792 | TASK [Install container runtime]
2025-10-09 00:09:36.343089 | controller | ok
2025-10-09 00:09:36.406347 | 
2025-10-09 00:09:36.406519 | LOOP [ensure-podman : Find distribution installation]
2025-10-09 00:09:36.436382 | controller | ok: "/var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-09 00:09:36.444120 | controller | included: /var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-09 00:09:36.451257 | 
2025-10-09 00:09:36.451381 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-09 00:10:53.811051 | controller | changed
2025-10-09 00:10:53.817614 | 
2025-10-09 00:10:53.817757 | TASK [ensure-podman : Fetch podman version]
2025-10-09 00:10:54.586343 | controller | Client:       Podman Engine
2025-10-09 00:10:54.586438 | controller | Version:      4.6.2
2025-10-09 00:10:54.586478 | controller | API Version:  4.6.2
2025-10-09 00:10:54.586518 | controller | Go Version:   go1.19.12
2025-10-09 00:10:54.586575 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-09 00:10:54.586616 | controller | OS/Arch:      linux/amd64
2025-10-09 00:10:54.963984 | controller | ok: Runtime: 0:00:00.217899
2025-10-09 00:10:54.974421 | 
2025-10-09 00:10:54.974525 | TASK [ensure-podman : Print podman version installed]
2025-10-09 00:10:55.013925 | Podman version: Client:       Podman Engine
2025-10-09 00:10:55.014185 | Version:      4.6.2
2025-10-09 00:10:55.014248 | API Version:  4.6.2
2025-10-09 00:10:55.014292 | Go Version:   go1.19.12
2025-10-09 00:10:55.014344 | Built:        Mon Aug 28 19:38:31 2023
2025-10-09 00:10:55.014387 | OS/Arch:      linux/amd64
2025-10-09 00:10:55.027231 | 
2025-10-09 00:10:55.027363 | TASK [ensure-podman : Validate podman engine]
2025-10-09 00:10:55.180004 | controller | skipping: Conditional result was False
2025-10-09 00:10:55.188143 | 
2025-10-09 00:10:55.188247 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-09 00:10:55.212448 | controller | skipping: Conditional result was False
2025-10-09 00:10:55.225095 | 
2025-10-09 00:10:55.225234 | TASK [Ensure python3.8 is present]
2025-10-09 00:10:55.249626 | controller | skipping: Conditional result was False
2025-10-09 00:10:55.257874 | 
2025-10-09 00:10:55.257995 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-09 00:10:55.280160 | controller | ok
2025-10-09 00:10:55.307476 | 
2025-10-09 00:10:55.307622 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-09 00:10:59.224041 | controller | ok: Nothing to do
2025-10-09 00:10:59.233033 | 
2025-10-09 00:10:59.233157 | TASK [our-ensure-python : Also install python3-devel]
2025-10-09 00:11:12.501245 | controller | changed
2025-10-09 00:11:12.529561 | 
2025-10-09 00:11:12.529869 | TASK [Run ensure-virtualenv role]
2025-10-09 00:11:12.554324 | controller | ok
2025-10-09 00:11:12.584531 | 
2025-10-09 00:11:12.584698 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-09 00:11:12.947224 | controller | /usr/bin/virtualenv
2025-10-09 00:11:13.223946 | controller | ok: Runtime: 0:00:00.004307
2025-10-09 00:11:13.238653 | 
2025-10-09 00:11:13.238902 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-09 00:11:13.272998 | controller | skipping: Conditional result was False
2025-10-09 00:11:13.273445 | controller | ok: All items complete
2025-10-09 00:11:13.273508 | 
2025-10-09 00:11:13.298913 | 
2025-10-09 00:11:13.299080 | TASK [Find the full path of the Python interpreter]
2025-10-09 00:11:13.762385 | controller | /usr/bin/python3
2025-10-09 00:11:13.971239 | controller | ok
2025-10-09 00:11:13.985824 | 
2025-10-09 00:11:13.986033 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-09 00:11:15.441231 | controller | created virtual environment CPython3.11.0.final.0-64 in 784ms
2025-10-09 00:11:15.503016 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-09 00:11:15.503064 | 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:11:15.503090 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-09 00:11:15.503110 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-09 00:11:15.655883 | controller | changed
2025-10-09 00:11:15.663738 | 
2025-10-09 00:11:15.663846 | TASK [Set selinux package]
2025-10-09 00:11:15.686299 | controller | ok
2025-10-09 00:11:15.692295 | 
2025-10-09 00:11:15.692392 | TASK [Set selinux package (Fedora)]
2025-10-09 00:11:15.722190 | controller | ok
2025-10-09 00:11:15.727393 | 
2025-10-09 00:11:15.727456 | TASK [Install selinux into virtualenv]
2025-10-09 00:11:18.412273 | controller | Collecting selinux-please-lie-to-me
2025-10-09 00:11:18.509128 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-09 00:11:19.039213 | controller | Collecting setuptools<50.0.0
2025-10-09 00:11:19.055749 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-09 00:11:19.181788 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-10-09 00:11:19.336099 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-09 00:11:19.336447 | controller |   Attempting uninstall: setuptools
2025-10-09 00:11:19.341423 | controller |     Found existing installation: setuptools 62.6.0
2025-10-09 00:11:19.453874 | controller |     Uninstalling setuptools-62.6.0:
2025-10-09 00:11:19.470162 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-09 00:11:20.229913 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-09 00:11:20.436790 | controller |
2025-10-09 00:11:20.649987 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-09 00:11:20.650032 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-09 00:11:20.884242 | controller | ok: Runtime: 0:00:04.453482
2025-10-09 00:11:20.893856 | 
2025-10-09 00:11:20.894164 | TASK [Install pytest-forked into virtualenv]
2025-10-09 00:11:22.102786 | controller | Collecting pytest-forked
2025-10-09 00:11:22.188780 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-09 00:11:22.248425 | controller | Collecting py
2025-10-09 00:11:22.260852 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-09 00:11:22.294604 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-10-09 00:11:22.465149 | controller | Collecting pytest>=3.10
2025-10-09 00:11:22.477625 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-09 00:11:22.527271 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.9 MB/s eta 0:00:00
2025-10-09 00:11:22.583207 | controller | Collecting iniconfig>=1
2025-10-09 00:11:22.595342 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-09 00:11:22.660964 | controller | Collecting packaging>=20
2025-10-09 00:11:22.672240 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-09 00:11:22.682033 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.1 MB/s eta 0:00:00
2025-10-09 00:11:22.727811 | controller | Collecting pluggy<2,>=1.5
2025-10-09 00:11:22.739680 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-09 00:11:22.813154 | controller | Collecting pygments>=2.7.2
2025-10-09 00:11:22.825170 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-09 00:11:22.919009 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.4 MB/s eta 0:00:00
2025-10-09 00:11:23.053862 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-09 00:11:25.356797 | 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:11:25.378100 | controller |
2025-10-09 00:11:25.562486 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-09 00:11:25.562539 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-09 00:11:26.073471 | controller | ok: Runtime: 0:00:04.189738
2025-10-09 00:11:26.085784 | 
2025-10-09 00:11:26.085969 | TASK [Update pip]
2025-10-09 00:11:27.263298 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-09 00:11:27.555356 | controller | Collecting pip
2025-10-09 00:11:27.652625 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-09 00:11:27.817129 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.9 MB/s eta 0:00:00
2025-10-09 00:11:27.976433 | controller | Installing collected packages: pip
2025-10-09 00:11:27.976730 | controller |   Attempting uninstall: pip
2025-10-09 00:11:27.981252 | controller |     Found existing installation: pip 22.2.2
2025-10-09 00:11:28.239495 | controller |     Uninstalling pip-22.2.2:
2025-10-09 00:11:28.269660 | controller |       Successfully uninstalled pip-22.2.2
2025-10-09 00:11:29.949864 | controller | Successfully installed pip-25.2
2025-10-09 00:11:30.257894 | controller | ok: Runtime: 0:00:03.504068
2025-10-09 00:11:30.263792 | 
2025-10-09 00:11:30.263858 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-09 00:11:30.776806 | controller | changed
2025-10-09 00:11:30.786658 | 
2025-10-09 00:11:30.786854 | TASK [Install ansible into virtualenv]
2025-10-09 00:11:31.888460 | controller | Processing ./src/github.com/ansible/ansible
2025-10-09 00:11:31.894994 | controller |   Installing build dependencies: started
2025-10-09 00:11:33.923787 | controller |   Installing build dependencies: finished with status 'done'
2025-10-09 00:11:35.448142 | controller |   Getting requirements to build wheel: started
2025-10-09 00:11:35.448211 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-09 00:11:36.369140 | controller |   Preparing metadata (pyproject.toml): started
2025-10-09 00:11:36.369192 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-09 00:11:36.374164 | 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:11:36.378975 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-09 00:11:36.939855 | controller | ERROR
2025-10-09 00:11:36.940175 | controller | {
2025-10-09 00:11:36.940241 | controller |   "delta": "0:00:05.298544",
2025-10-09 00:11:36.940285 | controller |   "end": "2025-10-09 00:11:36.527874",
2025-10-09 00:11:36.940324 | controller |   "msg": "non-zero return code",
2025-10-09 00:11:36.940380 | controller |   "rc": 1,
2025-10-09 00:11:36.940419 | controller |   "start": "2025-10-09 00:11:31.229330"
2025-10-09 00:11:36.940454 | controller | }
failure
2025-10-09 00:11:36.943651 | 
2025-10-09 00:11:36.943814 | PLAY RECAP
2025-10-09 00:11:36.943905 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-09 00:11:36.943951 | 
2025-10-09 00:11:37.082180 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-09 00:11:37.084912 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-09 00:11:37.723353 | 
2025-10-09 00:11:37.723489 | PLAY [all]
2025-10-09 00:11:37.746135 | 
2025-10-09 00:11:37.746294 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-09 00:11:38.520035 | controller | changed: non-zero return code
2025-10-09 00:11:38.533947 | 
2025-10-09 00:11:38.534301 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-09 00:11:38.562398 | controller | skipping: Conditional result was False
2025-10-09 00:11:38.577446 | 
2025-10-09 00:11:38.577627 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-09 00:11:38.606216 | 
2025-10-09 00:11:38.606461 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-09 00:11:38.632206 | 
2025-10-09 00:11:38.632424 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-09 00:11:38.657787 | controller | skipping: Conditional result was False
2025-10-09 00:11:38.668134 | 
2025-10-09 00:11:38.668276 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-09 00:11:38.705044 | 
2025-10-09 00:11:38.705266 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-09 00:11:38.720464 | controller | skipping: Conditional result was False
2025-10-09 00:11:38.730138 | 
2025-10-09 00:11:38.730312 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-09 00:11:38.746600 | controller | skipping: Conditional result was False
2025-10-09 00:11:38.755247 | 
2025-10-09 00:11:38.755355 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-09 00:11:38.770413 | controller | skipping: Conditional result was False
2025-10-09 00:11:38.808095 | 
2025-10-09 00:11:38.808219 | PLAY RECAP
2025-10-09 00:11:38.808264 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-09 00:11:38.808285 | 
2025-10-09 00:11:38.918603 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-09 00:11:38.919461 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-09 00:11:39.504953 | 
2025-10-09 00:11:39.505097 | PLAY [all:!appliance*]
2025-10-09 00:11:39.533706 | 
2025-10-09 00:11:39.533832 | TASK [unregister the node]
2025-10-09 00:11:39.668375 | controller | skipping: Conditional result was False
2025-10-09 00:11:39.677075 | 
2025-10-09 00:11:39.677206 | TASK [include_role : fetch-output]
2025-10-09 00:11:39.725317 | controller | ok
2025-10-09 00:11:39.762125 | 
2025-10-09 00:11:39.762273 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-09 00:11:39.849326 | controller | skipping: Conditional result was False
2025-10-09 00:11:39.855570 | 
2025-10-09 00:11:39.855672 | TASK [fetch-output : Set log path for single node]
2025-10-09 00:11:39.895482 | controller | ok
2025-10-09 00:11:39.901005 | 
2025-10-09 00:11:39.901072 | LOOP [fetch-output : Ensure local output dirs]
2025-10-09 00:11:40.372498 | controller -> localhost | ok: "/var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/logs"
2025-10-09 00:11:40.607082 | controller -> localhost | changed: "/var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/artifacts"
2025-10-09 00:11:40.828485 | controller -> localhost | changed: "/var/lib/zuul/builds/07a6aad27d5c45978cf43567add33200/work/docs"
2025-10-09 00:11:40.847730 | 
2025-10-09 00:11:40.847946 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-09 00:11:42.102970 | controller | changed:
2025-10-09 00:11:42.103292 | controller | .d..t...... ./
2025-10-09 00:11:42.103332 | controller | cd+++++++++ controller/
2025-10-09 00:11:42.103383 | controller | changed: All items complete
2025-10-09 00:11:42.103413 | 
2025-10-09 00:11:43.147633 | controller | changed: .d..t...... ./
2025-10-09 00:11:44.208977 | controller | changed: .d..t...... ./
2025-10-09 00:11:44.230224 | 
2025-10-09 00:11:44.230371 | TASK [include_role : fetch-output-openshift]
2025-10-09 00:11:44.257281 | controller | skipping: Conditional result was False
2025-10-09 00:11:44.268022 | 
2025-10-09 00:11:44.268180 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-09 00:11:44.306535 | controller | skipping: Conditional result was False
2025-10-09 00:11:44.321962 | controller | skipping: Conditional result was False
2025-10-09 00:11:44.365492 | 
2025-10-09 00:11:44.365634 | PLAY [localhost]
2025-10-09 00:11:44.384648 | 
2025-10-09 00:11:44.384783 | TASK [Run Zuul manifest role]
2025-10-09 00:11:44.403508 | localhost | ok
2025-10-09 00:11:44.419060 | 
2025-10-09 00:11:44.419185 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-09 00:11:44.858378 | localhost | changed
2025-10-09 00:11:44.863060 | 
2025-10-09 00:11:44.863130 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-09 00:11:44.907516 | localhost | ok
2025-10-09 00:11:44.924227 | 
2025-10-09 00:11:44.924358 | TASK [Set zuul-log-path fact]
2025-10-09 00:11:44.945189 | localhost | ok
2025-10-09 00:11:44.960991 | 
2025-10-09 00:11:44.961102 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-09 00:11:44.989806 | localhost | ok
2025-10-09 00:11:44.999940 | 
2025-10-09 00:11:45.000042 | LOOP [Run upload-logs-swift role]
2025-10-09 00:11:45.034982 | localhost | Output suppressed because no_log was given
2025-10-09 00:11:45.073754 | 
2025-10-09 00:11:45.073904 | TASK [Set zuul-log-path fact]
2025-10-09 00:11:45.099141 | localhost | skipping: Conditional result was False
2025-10-09 00:11:45.105363 | 
2025-10-09 00:11:45.105452 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-09 00:11:45.548519 | localhost -> localhost | ok: Runtime: 0:00:00.004646
2025-10-09 00:11:45.565717 | 
2025-10-09 00:11:45.565911 | TASK [upload-logs-swift : Upload logs to swift]