2025-10-29 00:11:59.015297 | Job console starting...
2025-10-29 00:11:59.026609 | Updating repositories
2025-10-29 00:11:59.123366 | Preparing job workspace
2025-10-29 00:12:02.827650 | Running Ansible setup...
2025-10-29 00:12:09.966869 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-29 00:12:10.639646 | 
2025-10-29 00:12:10.639813 | PLAY [localhost]
2025-10-29 00:12:10.649132 | 
2025-10-29 00:12:10.649209 | TASK [Gathering Facts]
2025-10-29 00:12:11.695262 | localhost | ok
2025-10-29 00:12:11.715878 | 
2025-10-29 00:12:11.716014 | TASK [Setup log path fact]
2025-10-29 00:12:11.738105 | localhost | ok
2025-10-29 00:12:11.759596 | 
2025-10-29 00:12:11.759762 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-29 00:12:11.790491 | localhost | ok
2025-10-29 00:12:11.806504 | 
2025-10-29 00:12:11.806647 | TASK [emit-job-header : Print job information]
2025-10-29 00:12:11.848884 | # Job Information
2025-10-29 00:12:11.849089 | Ansible Version: 2.15.12
2025-10-29 00:12:11.849133 | Job: ansible-test-sanity-docker-milestone
2025-10-29 00:12:11.849162 | Pipeline: periodic
2025-10-29 00:12:11.849187 | Executor: ze04.softwarefactory-project.io
2025-10-29 00:12:11.849211 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-29 00:12:11.849242 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/833/ansible/8338a0335f5c448a84062660ac7fdf39/
2025-10-29 00:12:11.849268 | Event ID: a4ea198b67664ad8b8b738cb49a7abfb
2025-10-29 00:12:11.855495 | 
2025-10-29 00:12:11.855724 | LOOP [emit-job-header : Print node information]
2025-10-29 00:12:11.968882 | localhost | ok:
2025-10-29 00:12:11.969182 | localhost | # Node Information
2025-10-29 00:12:11.969228 | localhost | Inventory Hostname: controller
2025-10-29 00:12:11.969262 | localhost | Hostname: ip-172-16-125-39
2025-10-29 00:12:11.969304 | localhost | Username: zuul-worker
2025-10-29 00:12:11.969350 | localhost | Distro: Fedora 37
2025-10-29 00:12:11.969387 | localhost | Provider: ansible-us-east-2
2025-10-29 00:12:11.969426 | localhost | Region: us-east-2
2025-10-29 00:12:11.969456 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-29 00:12:11.969481 | localhost | Product Name: t3.small
2025-10-29 00:12:11.969507 | localhost | Interface IP: 3.19.188.250
2025-10-29 00:12:11.987206 | 
2025-10-29 00:12:11.987314 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-29 00:12:12.380582 | localhost -> localhost | changed
2025-10-29 00:12:12.389031 | 
2025-10-29 00:12:12.389138 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-29 00:12:13.286092 | localhost -> localhost | changed
2025-10-29 00:12:13.324727 | 
2025-10-29 00:12:13.324826 | PLAY [all:!appliance*]
2025-10-29 00:12:13.341843 | 
2025-10-29 00:12:13.341965 | TASK [include_role : start-zuul-console]
2025-10-29 00:12:13.361199 | controller | ok
2025-10-29 00:12:13.375259 | 
2025-10-29 00:12:13.375354 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-29 00:12:14.083629 | controller | ok
2025-10-29 00:12:14.109665 | 
2025-10-29 00:12:14.109982 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-29 00:12:15.649348 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-29 00:12:15.657391 | 
2025-10-29 00:12:15.657491 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-29 00:12:15.794928 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.803141 | 
2025-10-29 00:12:15.803247 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-29 00:12:15.820068 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.831263 | 
2025-10-29 00:12:15.831367 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-29 00:12:15.858424 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.867838 | 
2025-10-29 00:12:15.867995 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-29 00:12:15.894090 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.901532 | 
2025-10-29 00:12:15.901638 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-29 00:12:15.930209 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.937417 | 
2025-10-29 00:12:15.937527 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-29 00:12:15.952077 | controller | skipping: Conditional result was False
2025-10-29 00:12:15.964976 | 
2025-10-29 00:12:15.965100 | TASK [Disable Fedora Modular]
2025-10-29 00:12:16.647115 | controller | changed
2025-10-29 00:12:16.661432 | 
2025-10-29 00:12:16.661618 | TASK [Enable EPEL]
2025-10-29 00:12:16.700109 | controller | skipping: Conditional result was False
2025-10-29 00:12:16.715035 | 
2025-10-29 00:12:16.715207 | TASK [Register the RHEL node]
2025-10-29 00:12:16.877611 | 
2025-10-29 00:12:16.877852 | TASK [Show the subscription-manager status]
2025-10-29 00:12:17.029267 | controller | skipping: Conditional result was False
2025-10-29 00:12:17.094650 | 
2025-10-29 00:12:17.094848 | TASK [Enable EPEL on RHEL]
2025-10-29 00:12:17.235869 | controller | skipping: Conditional result was False
2025-10-29 00:12:17.244174 | 
2025-10-29 00:12:17.244294 | TASK [Install git and tox]
2025-10-29 00:13:59.532051 | controller | changed
2025-10-29 00:13:59.541134 | 
2025-10-29 00:13:59.541227 | TASK [include_role : prepare-workspace]
2025-10-29 00:13:59.564022 | controller | ok
2025-10-29 00:13:59.590335 | 
2025-10-29 00:13:59.590691 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-29 00:14:00.200942 | controller | ok
2025-10-29 00:14:00.212798 | 
2025-10-29 00:14:00.212936 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-29 00:14:27.452955 | controller | Output suppressed because no_log was given
2025-10-29 00:14:27.471747 | 
2025-10-29 00:14:27.471856 | TASK [include_role : prepare-workspace-openshift]
2025-10-29 00:14:27.511361 | controller | skipping: Conditional result was False
2025-10-29 00:14:27.548597 | 
2025-10-29 00:14:27.548710 | PLAY [all:!appliance]
2025-10-29 00:14:27.587662 | 
2025-10-29 00:14:27.587824 | TASK [Run add-build-sshkey role (RSA)]
2025-10-29 00:14:27.622308 | controller | ok
2025-10-29 00:14:27.654266 | 
2025-10-29 00:14:27.654405 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-29 00:14:28.017094 | controller -> localhost | ok
2025-10-29 00:14:28.024657 | 
2025-10-29 00:14:28.024778 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-29 00:14:28.109425 | controller | ok
2025-10-29 00:14:28.140388 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-29 00:14:28.156137 | 
2025-10-29 00:14:28.156256 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-29 00:14:29.104192 | controller -> localhost | Generating public/private rsa key pair.
2025-10-29 00:14:29.104411 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_rsa.
2025-10-29 00:14:29.104460 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_rsa.pub.
2025-10-29 00:14:29.104492 | controller -> localhost | The key fingerprint is:
2025-10-29 00:14:29.104524 | controller -> localhost | SHA256:+bY8f4A67EKamm0Ge/pW1ASkLvwjHsn6RxR1q9mgb/Q zuul-build-sshkey
2025-10-29 00:14:29.104558 | controller -> localhost | The key's randomart image is:
2025-10-29 00:14:29.104605 | controller -> localhost | +---[RSA 2048]----+
2025-10-29 00:14:29.104632 | controller -> localhost | |     o+..        |
2025-10-29 00:14:29.104660 | controller -> localhost | |    .. ...       |
2025-10-29 00:14:29.104717 | controller -> localhost | |    ...o.        |
2025-10-29 00:14:29.104751 | controller -> localhost | | . ....=..       |
2025-10-29 00:14:29.104777 | controller -> localhost | |  o.o.+ S  .     |
2025-10-29 00:14:29.104813 | controller -> localhost | | ..+.oo. .. .    |
2025-10-29 00:14:29.104852 | controller -> localhost | |  =+o=o.E.o  .   |
2025-10-29 00:14:29.104902 | controller -> localhost | | o.=Oo. +o..  .  |
2025-10-29 00:14:29.104931 | controller -> localhost | |..*Xo  o..oo..   |
2025-10-29 00:14:29.104960 | controller -> localhost | +----[SHA256]-----+
2025-10-29 00:14:29.105048 | controller -> localhost | ok: Runtime: 0:00:00.122638
2025-10-29 00:14:29.129068 | 
2025-10-29 00:14:29.129224 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-29 00:14:29.189714 | controller | ok
2025-10-29 00:14:29.234084 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-29 00:14:29.262670 | 
2025-10-29 00:14:29.263722 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-29 00:14:29.346745 | controller | skipping: Conditional result was False
2025-10-29 00:14:29.354131 | 
2025-10-29 00:14:29.354247 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-29 00:14:30.001305 | controller | changed
2025-10-29 00:14:30.016768 | 
2025-10-29 00:14:30.016890 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-29 00:14:30.425366 | controller | ok
2025-10-29 00:14:30.434267 | 
2025-10-29 00:14:30.442133 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-29 00:14:31.855630 | controller | changed
2025-10-29 00:14:31.861503 | 
2025-10-29 00:14:31.861607 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-29 00:14:33.507978 | controller | changed
2025-10-29 00:14:33.521394 | 
2025-10-29 00:14:33.521882 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-29 00:14:33.568767 | controller | skipping: Conditional result was False
2025-10-29 00:14:33.576069 | 
2025-10-29 00:14:33.576177 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-29 00:14:33.999977 | controller -> localhost | changed
2025-10-29 00:14:34.027487 | 
2025-10-29 00:14:34.027630 | TASK [add-build-sshkey : Add back temp key]
2025-10-29 00:14:34.338303 | controller -> localhost | Identity added: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_rsa (zuul-build-sshkey)
2025-10-29 00:14:34.338498 | controller -> localhost | ok: Runtime: 0:00:00.009681
2025-10-29 00:14:34.347762 | 
2025-10-29 00:14:34.348398 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-29 00:14:34.865030 | controller | ok
2025-10-29 00:14:34.879133 | 
2025-10-29 00:14:34.879272 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-29 00:14:34.926448 | controller | skipping: Conditional result was False
2025-10-29 00:14:34.939664 | 
2025-10-29 00:14:34.939811 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-29 00:14:34.979531 | controller | ok
2025-10-29 00:14:34.998347 | 
2025-10-29 00:14:34.998489 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-29 00:14:35.257947 | controller -> localhost | ok
2025-10-29 00:14:35.264717 | 
2025-10-29 00:14:35.264821 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-29 00:14:35.294819 | controller | ok
2025-10-29 00:14:35.309978 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-29 00:14:35.316542 | 
2025-10-29 00:14:35.316652 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-29 00:14:35.607363 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-29 00:14:35.607587 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_ecdsa.
2025-10-29 00:14:35.607627 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_ecdsa.pub.
2025-10-29 00:14:35.607667 | controller -> localhost | The key fingerprint is:
2025-10-29 00:14:35.607716 | controller -> localhost | SHA256:G9SYmC3eHxcuc73CMAb2iSJICSPPaPKgbnYPosWH7Fo zuul-build-sshkey
2025-10-29 00:14:35.607742 | controller -> localhost | The key's randomart image is:
2025-10-29 00:14:35.607763 | controller -> localhost | +---[ECDSA 521]---+
2025-10-29 00:14:35.607784 | controller -> localhost | |+                |
2025-10-29 00:14:35.607804 | controller -> localhost | |.* .   + +       |
2025-10-29 00:14:35.607824 | controller -> localhost | |+.=   + B . .    |
2025-10-29 00:14:35.607844 | controller -> localhost | |++ . . = + o o   |
2025-10-29 00:14:35.607864 | controller -> localhost | |. o . o S X + .  |
2025-10-29 00:14:35.607885 | controller -> localhost | |.o . . . = X   . |
2025-10-29 00:14:35.607905 | controller -> localhost | | =Eo.   . . o .  |
2025-10-29 00:14:35.607925 | controller -> localhost | |++o.o        .   |
2025-10-29 00:14:35.607945 | controller -> localhost | |o..  .           |
2025-10-29 00:14:35.607965 | controller -> localhost | +----[SHA256]-----+
2025-10-29 00:14:35.608026 | controller -> localhost | ok: Runtime: 0:00:00.011099
2025-10-29 00:14:35.617377 | 
2025-10-29 00:14:35.617503 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-29 00:14:35.648436 | controller | ok
2025-10-29 00:14:35.657124 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-29 00:14:35.669350 | 
2025-10-29 00:14:35.669479 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-29 00:14:35.694944 | controller | skipping: Conditional result was False
2025-10-29 00:14:35.702171 | 
2025-10-29 00:14:35.702386 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-29 00:14:36.166840 | controller | changed
2025-10-29 00:14:36.175640 | 
2025-10-29 00:14:36.175774 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-29 00:14:36.523443 | controller | ok
2025-10-29 00:14:36.530865 | 
2025-10-29 00:14:36.530990 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-29 00:14:37.858573 | controller | changed
2025-10-29 00:14:37.865561 | 
2025-10-29 00:14:37.865655 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-29 00:14:39.187526 | controller | changed
2025-10-29 00:14:39.195669 | 
2025-10-29 00:14:39.195876 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-29 00:14:39.210447 | controller | skipping: Conditional result was False
2025-10-29 00:14:39.220207 | 
2025-10-29 00:14:39.220354 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-29 00:14:39.527638 | controller -> localhost | changed
2025-10-29 00:14:39.547019 | 
2025-10-29 00:14:39.547167 | TASK [add-build-sshkey : Add back temp key]
2025-10-29 00:14:39.841283 | controller -> localhost | Identity added: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/8338a0335f5c448a84062660ac7fdf39_id_ecdsa (zuul-build-sshkey)
2025-10-29 00:14:39.841580 | controller -> localhost | ok: Runtime: 0:00:00.007529
2025-10-29 00:14:39.853856 | 
2025-10-29 00:14:39.854015 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-29 00:14:40.207169 | controller | ok
2025-10-29 00:14:40.213624 | 
2025-10-29 00:14:40.213734 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-29 00:14:40.238469 | controller | skipping: Conditional result was False
2025-10-29 00:14:40.251485 | 
2025-10-29 00:14:40.251595 | TASK [include_role : remove-zuul-sshkey]
2025-10-29 00:14:40.266225 | controller | skipping: Conditional result was False
2025-10-29 00:14:40.274911 | 
2025-10-29 00:14:40.275012 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-29 00:14:40.583066 | controller | ok: "logs"
2025-10-29 00:14:40.583482 | controller | ok: All items complete
2025-10-29 00:14:40.583518 | 
2025-10-29 00:14:40.867524 | controller | ok: "artifacts"
2025-10-29 00:14:41.184981 | controller | ok: "docs"
2025-10-29 00:14:41.204247 | 
2025-10-29 00:14:41.204394 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-29 00:14:41.545406 | controller | changed: "logs"
2025-10-29 00:14:41.838809 | controller | changed: "artifacts"
2025-10-29 00:14:42.128117 | controller | changed: "docs"
2025-10-29 00:14:42.165469 | 
2025-10-29 00:14:42.165639 | PLAY RECAP
2025-10-29 00:14:42.165718 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-29 00:14:42.165799 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-29 00:14:42.165825 | 
2025-10-29 00:14:42.302567 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-29 00:14:42.303443 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-29 00:14:43.058460 | 
2025-10-29 00:14:43.058655 | PLAY [all]
2025-10-29 00:14:43.084383 | 
2025-10-29 00:14:43.084513 | TASK [Install binary dependencies]
2025-10-29 00:14:43.134496 | controller | ok
2025-10-29 00:14:43.169471 | 
2025-10-29 00:14:43.169605 | TASK [bindep : Include find tasks]
2025-10-29 00:14:43.199109 | controller | ok
2025-10-29 00:14:43.220343 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-29 00:14:43.227511 | 
2025-10-29 00:14:43.227631 | TASK [bindep : Look for bindep.txt]
2025-10-29 00:14:44.129922 | controller | ok
2025-10-29 00:14:44.136446 | 
2025-10-29 00:14:44.136542 | TASK [bindep : Define bindep_file fact]
2025-10-29 00:14:44.154202 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.167205 | 
2025-10-29 00:14:44.167422 | TASK [bindep : Look for other-requirements.txt]
2025-10-29 00:14:44.513621 | controller | ok
2025-10-29 00:14:44.519809 | 
2025-10-29 00:14:44.519911 | TASK [bindep : Define bindep_file fact]
2025-10-29 00:14:44.544089 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.551362 | 
2025-10-29 00:14:44.551488 | TASK [bindep : Look for bindep fallback file]
2025-10-29 00:14:44.575714 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.581931 | 
2025-10-29 00:14:44.582003 | TASK [bindep : Define bindep_file fact]
2025-10-29 00:14:44.605131 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.612782 | 
2025-10-29 00:14:44.612883 | TASK [bindep : Include bindep tasks]
2025-10-29 00:14:44.647757 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.654386 | 
2025-10-29 00:14:44.654463 | TASK [bindep : Include install tasks]
2025-10-29 00:14:44.678339 | controller | skipping: Conditional result was False
2025-10-29 00:14:44.701236 | 
2025-10-29 00:14:44.701373 | LOOP [bindep : Include package tasks]
2025-10-29 00:14:44.761531 | 
2025-10-29 00:14:44.761768 | TASK [Run test-setup role]
2025-10-29 00:14:44.783873 | controller | ok
2025-10-29 00:14:44.813019 | 
2025-10-29 00:14:44.813142 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-29 00:14:45.170765 | controller | ok
2025-10-29 00:14:45.179619 | 
2025-10-29 00:14:45.179742 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-29 00:14:45.378432 | controller | skipping: Conditional result was False
2025-10-29 00:14:45.420415 | 
2025-10-29 00:14:45.420526 | PLAY RECAP
2025-10-29 00:14:45.420572 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-29 00:14:45.420594 | 
2025-10-29 00:14:45.558525 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-29 00:14:45.559391 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-29 00:14:46.232829 | 
2025-10-29 00:14:46.232947 | PLAY [controller]
2025-10-29 00:14:46.252571 | 
2025-10-29 00:14:46.252721 | TASK [Create the /root directory]
2025-10-29 00:14:46.983355 | controller | ok
2025-10-29 00:14:46.999976 | 
2025-10-29 00:14:47.000159 | TASK [Install glibc-langpack-en]
2025-10-29 00:14:55.059793 | controller | ok: Nothing to do
2025-10-29 00:14:55.065787 | 
2025-10-29 00:14:55.065909 | TASK [Ensure controller directory exists]
2025-10-29 00:14:55.539125 | controller | changed
2025-10-29 00:14:55.546606 | 
2025-10-29 00:14:55.546742 | TASK [Install container runtime]
2025-10-29 00:14:55.599035 | controller | ok
2025-10-29 00:14:55.643559 | 
2025-10-29 00:14:55.643742 | LOOP [ensure-podman : Find distribution installation]
2025-10-29 00:14:55.673825 | controller | ok: "/var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-29 00:14:55.689506 | controller | included: /var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-29 00:14:55.696481 | 
2025-10-29 00:14:55.696570 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-29 00:16:15.026340 | controller | changed
2025-10-29 00:16:15.037245 | 
2025-10-29 00:16:15.037335 | TASK [ensure-podman : Fetch podman version]
2025-10-29 00:16:15.852809 | controller | Client:       Podman Engine
2025-10-29 00:16:15.852890 | controller | Version:      4.6.2
2025-10-29 00:16:15.852920 | controller | API Version:  4.6.2
2025-10-29 00:16:15.852947 | controller | Go Version:   go1.19.12
2025-10-29 00:16:15.852984 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-29 00:16:15.853011 | controller | OS/Arch:      linux/amd64
2025-10-29 00:16:16.205150 | controller | ok: Runtime: 0:00:00.245499
2025-10-29 00:16:16.212785 | 
2025-10-29 00:16:16.212892 | TASK [ensure-podman : Print podman version installed]
2025-10-29 00:16:16.254843 | Podman version: Client:       Podman Engine
2025-10-29 00:16:16.255015 | Version:      4.6.2
2025-10-29 00:16:16.255054 | API Version:  4.6.2
2025-10-29 00:16:16.255478 | Go Version:   go1.19.12
2025-10-29 00:16:16.255526 | Built:        Mon Aug 28 19:38:31 2023
2025-10-29 00:16:16.255553 | OS/Arch:      linux/amd64
2025-10-29 00:16:16.264188 | 
2025-10-29 00:16:16.264313 | TASK [ensure-podman : Validate podman engine]
2025-10-29 00:16:16.397617 | controller | skipping: Conditional result was False
2025-10-29 00:16:16.406924 | 
2025-10-29 00:16:16.407072 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-29 00:16:16.423276 | controller | skipping: Conditional result was False
2025-10-29 00:16:16.438410 | 
2025-10-29 00:16:16.438601 | TASK [Ensure python3.8 is present]
2025-10-29 00:16:16.469003 | controller | skipping: Conditional result was False
2025-10-29 00:16:16.479189 | 
2025-10-29 00:16:16.479301 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-29 00:16:16.511031 | controller | ok
2025-10-29 00:16:16.584254 | 
2025-10-29 00:16:16.584385 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-29 00:16:20.354329 | controller | ok: Nothing to do
2025-10-29 00:16:20.361022 | 
2025-10-29 00:16:20.361127 | TASK [our-ensure-python : Also install python3-devel]
2025-10-29 00:16:33.679744 | controller | changed
2025-10-29 00:16:33.693372 | 
2025-10-29 00:16:33.693497 | TASK [Run ensure-virtualenv role]
2025-10-29 00:16:33.727365 | controller | ok
2025-10-29 00:16:33.771846 | 
2025-10-29 00:16:33.772115 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-29 00:16:34.199161 | controller | /usr/bin/virtualenv
2025-10-29 00:16:34.431032 | controller | ok: Runtime: 0:00:00.004521
2025-10-29 00:16:34.439598 | 
2025-10-29 00:16:34.439735 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-29 00:16:34.462349 | controller | skipping: Conditional result was False
2025-10-29 00:16:34.462703 | controller | ok: All items complete
2025-10-29 00:16:34.462748 | 
2025-10-29 00:16:34.476372 | 
2025-10-29 00:16:34.476531 | TASK [Find the full path of the Python interpreter]
2025-10-29 00:16:34.985649 | controller | /usr/bin/python3
2025-10-29 00:16:35.166466 | controller | ok
2025-10-29 00:16:35.172119 | 
2025-10-29 00:16:35.172198 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-29 00:16:36.594974 | controller | created virtual environment CPython3.11.0.final.0-64 in 776ms
2025-10-29 00:16:36.647941 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-29 00:16:36.647998 | 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-29 00:16:36.648016 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-29 00:16:36.648039 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-29 00:16:36.817669 | controller | changed
2025-10-29 00:16:36.828868 | 
2025-10-29 00:16:36.829009 | TASK [Set selinux package]
2025-10-29 00:16:36.876484 | controller | ok
2025-10-29 00:16:36.908963 | 
2025-10-29 00:16:36.909156 | TASK [Set selinux package (Fedora)]
2025-10-29 00:16:36.954878 | controller | ok
2025-10-29 00:16:36.972392 | 
2025-10-29 00:16:36.972574 | TASK [Install selinux into virtualenv]
2025-10-29 00:16:39.687970 | controller | Collecting selinux-please-lie-to-me
2025-10-29 00:16:39.774786 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-29 00:16:40.298138 | controller | Collecting setuptools<50.0.0
2025-10-29 00:16:40.312414 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-29 00:16:40.433102 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.9 MB/s eta 0:00:00
2025-10-29 00:16:40.581531 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-29 00:16:40.581831 | controller |   Attempting uninstall: setuptools
2025-10-29 00:16:40.586735 | controller |     Found existing installation: setuptools 62.6.0
2025-10-29 00:16:40.698242 | controller |     Uninstalling setuptools-62.6.0:
2025-10-29 00:16:40.713361 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-29 00:16:41.466587 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-29 00:16:41.672714 | controller |
2025-10-29 00:16:41.887064 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-29 00:16:41.887111 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-29 00:16:42.202949 | controller | ok: Runtime: 0:00:04.347629
2025-10-29 00:16:42.212224 | 
2025-10-29 00:16:42.212350 | TASK [Install pytest-forked into virtualenv]
2025-10-29 00:16:43.467132 | controller | Collecting pytest-forked
2025-10-29 00:16:43.559152 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-29 00:16:43.630669 | controller | Collecting py
2025-10-29 00:16:43.644966 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-29 00:16:43.679636 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-29 00:16:43.852667 | controller | Collecting pytest>=3.10
2025-10-29 00:16:43.866619 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-29 00:16:43.908056 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 9.6 MB/s eta 0:00:00
2025-10-29 00:16:43.964921 | controller | Collecting iniconfig>=1
2025-10-29 00:16:43.978965 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-29 00:16:44.046193 | controller | Collecting packaging>=20
2025-10-29 00:16:44.059724 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-29 00:16:44.070004 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.4 MB/s eta 0:00:00
2025-10-29 00:16:44.134050 | controller | Collecting pluggy<2,>=1.5
2025-10-29 00:16:44.147777 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-29 00:16:44.223456 | controller | Collecting pygments>=2.7.2
2025-10-29 00:16:44.237501 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-29 00:16:44.328808 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.9 MB/s eta 0:00:00
2025-10-29 00:16:44.458835 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-29 00:16:46.732894 | 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-29 00:16:46.748879 | controller |
2025-10-29 00:16:46.932540 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-29 00:16:46.932592 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-29 00:16:47.394359 | controller | ok: Runtime: 0:00:04.189638
2025-10-29 00:16:47.402636 | 
2025-10-29 00:16:47.402790 | TASK [Update pip]
2025-10-29 00:16:49.082856 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-29 00:16:49.336124 | controller | Collecting pip
2025-10-29 00:16:49.424434 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-29 00:16:49.631036 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.8 MB/s eta 0:00:00
2025-10-29 00:16:49.775624 | controller | Installing collected packages: pip
2025-10-29 00:16:49.775927 | controller |   Attempting uninstall: pip
2025-10-29 00:16:49.780280 | controller |     Found existing installation: pip 22.2.2
2025-10-29 00:16:50.037273 | controller |     Uninstalling pip-22.2.2:
2025-10-29 00:16:50.066539 | controller |       Successfully uninstalled pip-22.2.2
2025-10-29 00:16:51.868044 | controller | Successfully installed pip-25.3
2025-10-29 00:16:52.547048 | controller | ok: Runtime: 0:00:03.683686
2025-10-29 00:16:52.554314 | 
2025-10-29 00:16:52.554448 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-29 00:16:53.105976 | controller | changed
2025-10-29 00:16:53.112309 | 
2025-10-29 00:16:53.112418 | TASK [Install ansible into virtualenv]
2025-10-29 00:16:54.114596 | controller | Processing ./src/github.com/ansible/ansible
2025-10-29 00:16:54.121079 | controller |   Installing build dependencies: started
2025-10-29 00:16:56.035419 | controller |   Installing build dependencies: finished with status 'done'
2025-10-29 00:16:57.570788 | controller |   Getting requirements to build wheel: started
2025-10-29 00:16:57.570853 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-29 00:16:58.492385 | controller |   Preparing metadata (pyproject.toml): started
2025-10-29 00:16:58.492436 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-29 00:16:58.496515 | 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-29 00:16:58.496563 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-29 00:16:58.784734 | controller | ERROR
2025-10-29 00:16:58.784943 | controller | {
2025-10-29 00:16:58.784984 | controller |   "delta": "0:00:05.100142",
2025-10-29 00:16:58.785013 | controller |   "end": "2025-10-29 00:16:58.643070",
2025-10-29 00:16:58.785038 | controller |   "msg": "non-zero return code",
2025-10-29 00:16:58.785243 | controller |   "rc": 1,
2025-10-29 00:16:58.785289 | controller |   "start": "2025-10-29 00:16:53.542928"
2025-10-29 00:16:58.785322 | controller | }
failure
2025-10-29 00:16:58.788964 | 
2025-10-29 00:16:58.789034 | PLAY RECAP
2025-10-29 00:16:58.789092 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-29 00:16:58.789125 | 
2025-10-29 00:16:58.958074 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-29 00:16:58.959331 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-29 00:16:59.692546 | 
2025-10-29 00:16:59.692674 | PLAY [all]
2025-10-29 00:16:59.717177 | 
2025-10-29 00:16:59.717300 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-29 00:17:00.544523 | controller | changed: non-zero return code
2025-10-29 00:17:00.554029 | 
2025-10-29 00:17:00.554204 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-29 00:17:00.584639 | controller | skipping: Conditional result was False
2025-10-29 00:17:00.593620 | 
2025-10-29 00:17:00.593763 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-29 00:17:00.626086 | 
2025-10-29 00:17:00.626252 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-29 00:17:00.646570 | 
2025-10-29 00:17:00.646836 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-29 00:17:00.663951 | controller | skipping: Conditional result was False
2025-10-29 00:17:00.671447 | 
2025-10-29 00:17:00.671596 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-29 00:17:00.695996 | 
2025-10-29 00:17:00.696228 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-29 00:17:00.712640 | controller | skipping: Conditional result was False
2025-10-29 00:17:00.719989 | 
2025-10-29 00:17:00.720117 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-29 00:17:00.736922 | controller | skipping: Conditional result was False
2025-10-29 00:17:00.744011 | 
2025-10-29 00:17:00.744122 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-29 00:17:00.758011 | controller | skipping: Conditional result was False
2025-10-29 00:17:00.785696 | 
2025-10-29 00:17:00.785788 | PLAY RECAP
2025-10-29 00:17:00.785834 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-29 00:17:00.785857 | 
2025-10-29 00:17:00.926648 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-29 00:17:00.945028 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-29 00:17:01.726028 | 
2025-10-29 00:17:01.726191 | PLAY [all:!appliance*]
2025-10-29 00:17:01.764211 | 
2025-10-29 00:17:01.764371 | TASK [unregister the node]
2025-10-29 00:17:01.921096 | controller | skipping: Conditional result was False
2025-10-29 00:17:01.930325 | 
2025-10-29 00:17:01.930499 | TASK [include_role : fetch-output]
2025-10-29 00:17:01.974973 | controller | ok
2025-10-29 00:17:02.001335 | 
2025-10-29 00:17:02.001458 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-29 00:17:02.056233 | controller | skipping: Conditional result was False
2025-10-29 00:17:02.063634 | 
2025-10-29 00:17:02.063869 | TASK [fetch-output : Set log path for single node]
2025-10-29 00:17:02.105704 | controller | ok
2025-10-29 00:17:02.112528 | 
2025-10-29 00:17:02.112636 | LOOP [fetch-output : Ensure local output dirs]
2025-10-29 00:17:02.629147 | controller -> localhost | ok: "/var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/logs"
2025-10-29 00:17:02.926708 | controller -> localhost | changed: "/var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/artifacts"
2025-10-29 00:17:03.210267 | controller -> localhost | changed: "/var/lib/zuul/builds/8338a0335f5c448a84062660ac7fdf39/work/docs"
2025-10-29 00:17:03.237758 | 
2025-10-29 00:17:03.237904 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-29 00:17:04.501467 | controller | changed:
2025-10-29 00:17:04.501741 | controller | .d..t...... ./
2025-10-29 00:17:04.501775 | controller | cd+++++++++ controller/
2025-10-29 00:17:04.501809 | controller | changed: All items complete
2025-10-29 00:17:04.501830 | 
2025-10-29 00:17:05.591222 | controller | changed: .d..t...... ./
2025-10-29 00:17:06.591071 | controller | changed: .d..t...... ./
2025-10-29 00:17:06.615907 | 
2025-10-29 00:17:06.616041 | TASK [include_role : fetch-output-openshift]
2025-10-29 00:17:06.631997 | controller | skipping: Conditional result was False
2025-10-29 00:17:06.650967 | 
2025-10-29 00:17:06.651116 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-29 00:17:06.693018 | controller | skipping: Conditional result was False
2025-10-29 00:17:06.710390 | controller | skipping: Conditional result was False
2025-10-29 00:17:06.767911 | 
2025-10-29 00:17:06.768025 | PLAY [localhost]
2025-10-29 00:17:06.788142 | 
2025-10-29 00:17:06.788271 | TASK [Run Zuul manifest role]
2025-10-29 00:17:06.807355 | localhost | ok
2025-10-29 00:17:06.824080 | 
2025-10-29 00:17:06.824195 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-29 00:17:07.267005 | localhost | changed
2025-10-29 00:17:07.272243 | 
2025-10-29 00:17:07.272323 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-29 00:17:07.302723 | localhost | ok
2025-10-29 00:17:07.312136 | 
2025-10-29 00:17:07.312238 | TASK [Set zuul-log-path fact]
2025-10-29 00:17:07.331440 | localhost | ok
2025-10-29 00:17:07.346947 | 
2025-10-29 00:17:07.347050 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-29 00:17:07.379318 | localhost | ok
2025-10-29 00:17:07.390444 | 
2025-10-29 00:17:07.390563 | LOOP [Run upload-logs-swift role]
2025-10-29 00:17:07.426135 | localhost | Output suppressed because no_log was given
2025-10-29 00:17:07.458285 | 
2025-10-29 00:17:07.458405 | TASK [Set zuul-log-path fact]
2025-10-29 00:17:07.483193 | localhost | skipping: Conditional result was False
2025-10-29 00:17:07.488390 | 
2025-10-29 00:17:07.488472 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-29 00:17:07.914583 | localhost -> localhost | ok: Runtime: 0:00:00.006969
2025-10-29 00:17:07.921587 | 
2025-10-29 00:17:07.921708 | TASK [upload-logs-swift : Upload logs to swift]