2025-09-17 00:11:42.476146 | Job console starting...
2025-09-17 00:11:42.488434 | Updating repositories
2025-09-17 00:11:42.646656 | Preparing job workspace
2025-09-17 00:11:46.388734 | Running Ansible setup...
2025-09-17 00:11:52.055069 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:11:52.697650 | 
2025-09-17 00:11:52.697789 | PLAY [localhost]
2025-09-17 00:11:52.706056 | 
2025-09-17 00:11:52.706125 | TASK [Gathering Facts]
2025-09-17 00:11:53.738570 | localhost | ok
2025-09-17 00:11:53.759753 | 
2025-09-17 00:11:53.759860 | TASK [Setup log path fact]
2025-09-17 00:11:53.783099 | localhost | ok
2025-09-17 00:11:53.814759 | 
2025-09-17 00:11:53.814987 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:11:53.852123 | localhost | ok
2025-09-17 00:11:53.871184 | 
2025-09-17 00:11:53.871301 | TASK [emit-job-header : Print job information]
2025-09-17 00:11:53.922062 | # Job Information
2025-09-17 00:11:53.922295 | Ansible Version: 2.15.12
2025-09-17 00:11:53.922352 | Job: ansible-test-sanity-docker-milestone
2025-09-17 00:11:53.922391 | Pipeline: periodic
2025-09-17 00:11:53.922419 | Executor: ze02.softwarefactory-project.io
2025-09-17 00:11:53.922444 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-17 00:11:53.922472 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/81a/ansible/81a3860b72fe46c6857133c121b55daf/
2025-09-17 00:11:53.922497 | Event ID: eca5199f70dd4f21ae7c1e30717f8aa4
2025-09-17 00:11:53.927487 | 
2025-09-17 00:11:53.927574 | LOOP [emit-job-header : Print node information]
2025-09-17 00:11:54.033435 | localhost | ok:
2025-09-17 00:11:54.033758 | localhost | # Node Information
2025-09-17 00:11:54.033801 | localhost | Inventory Hostname: controller
2025-09-17 00:11:54.033829 | localhost | Hostname: ip-172-16-107-118
2025-09-17 00:11:54.033854 | localhost | Username: zuul-worker
2025-09-17 00:11:54.033882 | localhost | Distro: Fedora 37
2025-09-17 00:11:54.033908 | localhost | Provider: ansible-us-east-2
2025-09-17 00:11:54.033931 | localhost | Region: us-east-2
2025-09-17 00:11:54.033954 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-17 00:11:54.033976 | localhost | Product Name: t3.small
2025-09-17 00:11:54.033999 | localhost | Interface IP: 18.224.140.143
2025-09-17 00:11:54.054155 | 
2025-09-17 00:11:54.054244 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-17 00:11:54.465320 | localhost -> localhost | changed
2025-09-17 00:11:54.476919 | 
2025-09-17 00:11:54.477061 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-17 00:11:55.298074 | localhost -> localhost | changed
2025-09-17 00:11:55.332773 | 
2025-09-17 00:11:55.332854 | PLAY [all:!appliance*]
2025-09-17 00:11:55.376385 | 
2025-09-17 00:11:55.376502 | TASK [include_role : start-zuul-console]
2025-09-17 00:11:55.398911 | controller | ok
2025-09-17 00:11:55.416535 | 
2025-09-17 00:11:55.416600 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-17 00:11:56.056017 | controller | ok
2025-09-17 00:11:56.067768 | 
2025-09-17 00:11:56.067833 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-17 00:11:58.032509 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-17 00:11:58.045836 | 
2025-09-17 00:11:58.045952 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-17 00:11:58.211628 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.217838 | 
2025-09-17 00:11:58.217912 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-17 00:11:58.231436 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.237298 | 
2025-09-17 00:11:58.237368 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-17 00:11:58.250338 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.256334 | 
2025-09-17 00:11:58.256402 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-17 00:11:58.279630 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.285190 | 
2025-09-17 00:11:58.285255 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-17 00:11:58.308472 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.314072 | 
2025-09-17 00:11:58.314136 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-17 00:11:58.337188 | controller | skipping: Conditional result was False
2025-09-17 00:11:58.348832 | 
2025-09-17 00:11:58.348901 | TASK [Disable Fedora Modular]
2025-09-17 00:11:59.205529 | controller | changed
2025-09-17 00:11:59.217571 | 
2025-09-17 00:11:59.217752 | TASK [Enable EPEL]
2025-09-17 00:11:59.245349 | controller | skipping: Conditional result was False
2025-09-17 00:11:59.258874 | 
2025-09-17 00:11:59.259017 | TASK [Register the RHEL node]
2025-09-17 00:11:59.407241 | 
2025-09-17 00:11:59.407417 | TASK [Show the subscription-manager status]
2025-09-17 00:11:59.566183 | controller | skipping: Conditional result was False
2025-09-17 00:11:59.579889 | 
2025-09-17 00:11:59.580032 | TASK [Enable EPEL on RHEL]
2025-09-17 00:11:59.737837 | controller | skipping: Conditional result was False
2025-09-17 00:11:59.746919 | 
2025-09-17 00:11:59.747057 | TASK [Install git and tox]
2025-09-17 00:13:29.813160 | controller | changed
2025-09-17 00:13:29.819344 | 
2025-09-17 00:13:29.819405 | TASK [include_role : prepare-workspace]
2025-09-17 00:13:29.848939 | controller | ok
2025-09-17 00:13:29.868919 | 
2025-09-17 00:13:29.868987 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-17 00:13:30.389732 | controller | ok
2025-09-17 00:13:30.398975 | 
2025-09-17 00:13:30.399064 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-17 00:13:42.356855 | controller | Output suppressed because no_log was given
2025-09-17 00:13:42.372251 | 
2025-09-17 00:13:42.372368 | TASK [include_role : prepare-workspace-openshift]
2025-09-17 00:13:42.394470 | controller | skipping: Conditional result was False
2025-09-17 00:13:42.425574 | 
2025-09-17 00:13:42.425754 | PLAY [all:!appliance]
2025-09-17 00:13:42.444424 | 
2025-09-17 00:13:42.444530 | TASK [Run add-build-sshkey role (RSA)]
2025-09-17 00:13:42.477022 | controller | ok
2025-09-17 00:13:42.493173 | 
2025-09-17 00:13:42.493281 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:13:42.772529 | controller -> localhost | ok
2025-09-17 00:13:42.783118 | 
2025-09-17 00:13:42.783227 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:13:42.926689 | controller | ok
2025-09-17 00:13:42.944342 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:13:42.952273 | 
2025-09-17 00:13:42.952356 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:13:43.464436 | controller -> localhost | Generating public/private rsa key pair.
2025-09-17 00:13:43.465141 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_rsa.
2025-09-17 00:13:43.465352 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_rsa.pub.
2025-09-17 00:13:43.465408 | controller -> localhost | The key fingerprint is:
2025-09-17 00:13:43.465453 | controller -> localhost | SHA256:Mgj+0Mlfmg8rpgwwSe2BWnK92CsCQ3Pp06pnM4B4k90 zuul-build-sshkey
2025-09-17 00:13:43.465497 | controller -> localhost | The key's randomart image is:
2025-09-17 00:13:43.465545 | controller -> localhost | +---[RSA 2048]----+
2025-09-17 00:13:43.465588 | controller -> localhost | |                 |
2025-09-17 00:13:43.465632 | controller -> localhost | |  o..            |
2025-09-17 00:13:43.465704 | controller -> localhost | |.=+=.            |
2025-09-17 00:13:43.465757 | controller -> localhost | |+*=*o+           |
2025-09-17 00:13:43.465798 | controller -> localhost | |X +*Boo S        |
2025-09-17 00:13:43.465863 | controller -> localhost | |=++o+oE*         |
2025-09-17 00:13:43.465919 | controller -> localhost | |o.ooo =          |
2025-09-17 00:13:43.465964 | controller -> localhost | | +.*o  +         |
2025-09-17 00:13:43.466006 | controller -> localhost | | .=oo.. .        |
2025-09-17 00:13:43.466052 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:13:43.466193 | controller -> localhost | ok: Runtime: 0:00:00.090523
2025-09-17 00:13:43.478472 | 
2025-09-17 00:13:43.478714 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:13:43.513786 | controller | ok
2025-09-17 00:13:43.530286 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:13:43.545734 | 
2025-09-17 00:13:43.545920 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:13:43.582430 | controller | skipping: Conditional result was False
2025-09-17 00:13:43.589734 | 
2025-09-17 00:13:43.589803 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:13:44.617619 | controller | changed
2025-09-17 00:13:44.633595 | 
2025-09-17 00:13:44.633774 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:13:44.973321 | controller | ok
2025-09-17 00:13:44.986374 | 
2025-09-17 00:13:44.986520 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:13:46.254771 | controller | changed
2025-09-17 00:13:46.262968 | 
2025-09-17 00:13:46.263054 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:13:47.513136 | controller | changed
2025-09-17 00:13:47.528356 | 
2025-09-17 00:13:47.528511 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:13:47.566538 | controller | skipping: Conditional result was False
2025-09-17 00:13:47.580951 | 
2025-09-17 00:13:47.581055 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:13:47.973010 | controller -> localhost | changed
2025-09-17 00:13:47.984931 | 
2025-09-17 00:13:47.984997 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:13:48.313500 | controller -> localhost | Identity added: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_rsa (zuul-build-sshkey)
2025-09-17 00:13:48.313770 | controller -> localhost | ok: Runtime: 0:00:00.014876
2025-09-17 00:13:48.321690 | 
2025-09-17 00:13:48.321754 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:13:48.821814 | controller | ok
2025-09-17 00:13:48.838955 | 
2025-09-17 00:13:48.839048 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:13:48.876872 | controller | skipping: Conditional result was False
2025-09-17 00:13:48.896322 | 
2025-09-17 00:13:48.896426 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-17 00:13:48.931526 | controller | ok
2025-09-17 00:13:48.959014 | 
2025-09-17 00:13:48.959086 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:13:49.239370 | controller -> localhost | ok
2025-09-17 00:13:49.255148 | 
2025-09-17 00:13:49.255449 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:13:49.283184 | controller | ok
2025-09-17 00:13:49.302646 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:13:49.312751 | 
2025-09-17 00:13:49.312832 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:13:49.592221 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-17 00:13:49.592500 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_ecdsa.
2025-09-17 00:13:49.592532 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_ecdsa.pub.
2025-09-17 00:13:49.592562 | controller -> localhost | The key fingerprint is:
2025-09-17 00:13:49.592582 | controller -> localhost | SHA256:vcFe2/oJaXVb92yz0LvFvE7bwnkDB3vGpWFU6iFoRAI zuul-build-sshkey
2025-09-17 00:13:49.592601 | controller -> localhost | The key's randomart image is:
2025-09-17 00:13:49.592621 | controller -> localhost | +---[ECDSA 521]---+
2025-09-17 00:13:49.592639 | controller -> localhost | |      E...o    ..|
2025-09-17 00:13:49.592656 | controller -> localhost | |         o .  .. |
2025-09-17 00:13:49.592695 | controller -> localhost | |          o ..o  |
2025-09-17 00:13:49.592713 | controller -> localhost | |         +   +o..|
2025-09-17 00:13:49.592730 | controller -> localhost | |        S + ..*o=|
2025-09-17 00:13:49.592747 | controller -> localhost | |         . + BoX=|
2025-09-17 00:13:49.592764 | controller -> localhost | |          o =o**B|
2025-09-17 00:13:49.592780 | controller -> localhost | |           . o*+X|
2025-09-17 00:13:49.592797 | controller -> localhost | |            ..+X+|
2025-09-17 00:13:49.592813 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:13:49.592883 | controller -> localhost | ok: Runtime: 0:00:00.014844
2025-09-17 00:13:49.603579 | 
2025-09-17 00:13:49.603691 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:13:49.642045 | controller | ok
2025-09-17 00:13:49.655238 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:13:49.667303 | 
2025-09-17 00:13:49.667375 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:13:49.693983 | controller | skipping: Conditional result was False
2025-09-17 00:13:49.703575 | 
2025-09-17 00:13:49.703652 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:13:50.133003 | controller | changed
2025-09-17 00:13:50.140501 | 
2025-09-17 00:13:50.140583 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:13:50.490808 | controller | ok
2025-09-17 00:13:50.507898 | 
2025-09-17 00:13:50.507994 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:13:51.789344 | controller | changed
2025-09-17 00:13:51.807922 | 
2025-09-17 00:13:51.808015 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:13:53.068882 | controller | changed
2025-09-17 00:13:53.078995 | 
2025-09-17 00:13:53.079089 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:13:53.127833 | controller | skipping: Conditional result was False
2025-09-17 00:13:53.142304 | 
2025-09-17 00:13:53.142426 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:13:53.417608 | controller -> localhost | changed
2025-09-17 00:13:53.436882 | 
2025-09-17 00:13:53.436973 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:13:53.738923 | controller -> localhost | Identity added: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/81a3860b72fe46c6857133c121b55daf_id_ecdsa (zuul-build-sshkey)
2025-09-17 00:13:53.739284 | controller -> localhost | ok: Runtime: 0:00:00.015879
2025-09-17 00:13:53.748333 | 
2025-09-17 00:13:53.748421 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:13:54.088495 | controller | ok
2025-09-17 00:13:54.097844 | 
2025-09-17 00:13:54.097937 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:13:54.145885 | controller | skipping: Conditional result was False
2025-09-17 00:13:54.161327 | 
2025-09-17 00:13:54.161415 | TASK [include_role : remove-zuul-sshkey]
2025-09-17 00:13:54.188023 | controller | skipping: Conditional result was False
2025-09-17 00:13:54.196993 | 
2025-09-17 00:13:54.197082 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-17 00:13:54.518212 | controller | ok: "logs"
2025-09-17 00:13:54.518669 | controller | ok: All items complete
2025-09-17 00:13:54.518764 | 
2025-09-17 00:13:54.800346 | controller | ok: "artifacts"
2025-09-17 00:13:55.087304 | controller | ok: "docs"
2025-09-17 00:13:55.150699 | 
2025-09-17 00:13:55.150854 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-17 00:13:55.485855 | controller | changed: "logs"
2025-09-17 00:13:55.764001 | controller | changed: "artifacts"
2025-09-17 00:13:56.050671 | controller | changed: "docs"
2025-09-17 00:13:56.104371 | 
2025-09-17 00:13:56.104490 | PLAY RECAP
2025-09-17 00:13:56.104546 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-17 00:13:56.104581 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-17 00:13:56.104605 | 
2025-09-17 00:13:56.231370 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:13:56.232288 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:13:56.780085 | 
2025-09-17 00:13:56.780227 | PLAY [all]
2025-09-17 00:13:56.802500 | 
2025-09-17 00:13:56.802642 | TASK [Install binary dependencies]
2025-09-17 00:13:56.850131 | controller | ok
2025-09-17 00:13:56.870327 | 
2025-09-17 00:13:56.870451 | TASK [bindep : Include find tasks]
2025-09-17 00:13:56.900172 | controller | ok
2025-09-17 00:13:56.907565 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-17 00:13:56.913558 | 
2025-09-17 00:13:56.913623 | TASK [bindep : Look for bindep.txt]
2025-09-17 00:13:57.428041 | controller | ok
2025-09-17 00:13:57.441597 | 
2025-09-17 00:13:57.441809 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:13:57.460795 | controller | skipping: Conditional result was False
2025-09-17 00:13:57.474330 | 
2025-09-17 00:13:57.474476 | TASK [bindep : Look for other-requirements.txt]
2025-09-17 00:13:57.785028 | controller | ok
2025-09-17 00:13:57.797071 | 
2025-09-17 00:13:57.797220 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:13:57.834540 | controller | skipping: Conditional result was False
2025-09-17 00:13:57.845809 | 
2025-09-17 00:13:57.845903 | TASK [bindep : Look for bindep fallback file]
2025-09-17 00:13:57.881781 | controller | skipping: Conditional result was False
2025-09-17 00:13:57.897111 | 
2025-09-17 00:13:57.897274 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:13:57.936564 | controller | skipping: Conditional result was False
2025-09-17 00:13:57.952894 | 
2025-09-17 00:13:57.953049 | TASK [bindep : Include bindep tasks]
2025-09-17 00:13:57.992280 | controller | skipping: Conditional result was False
2025-09-17 00:13:58.011038 | 
2025-09-17 00:13:58.011203 | TASK [bindep : Include install tasks]
2025-09-17 00:13:58.039949 | controller | skipping: Conditional result was False
2025-09-17 00:13:58.055894 | 
2025-09-17 00:13:58.056051 | LOOP [bindep : Include package tasks]
2025-09-17 00:13:58.129203 | 
2025-09-17 00:13:58.129499 | TASK [Run test-setup role]
2025-09-17 00:13:58.158191 | controller | ok
2025-09-17 00:13:58.192838 | 
2025-09-17 00:13:58.192991 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-17 00:13:58.507557 | controller | ok
2025-09-17 00:13:58.520169 | 
2025-09-17 00:13:58.520304 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-17 00:13:58.656431 | controller | skipping: Conditional result was False
2025-09-17 00:13:58.708316 | 
2025-09-17 00:13:58.708424 | PLAY RECAP
2025-09-17 00:13:58.708478 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:13:58.708506 | 
2025-09-17 00:13:58.818480 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:13:58.820185 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:13:59.387923 | 
2025-09-17 00:13:59.388053 | PLAY [controller]
2025-09-17 00:13:59.407591 | 
2025-09-17 00:13:59.407707 | TASK [Create the /root directory]
2025-09-17 00:14:00.099137 | controller | ok
2025-09-17 00:14:00.111471 | 
2025-09-17 00:14:00.111622 | TASK [Install glibc-langpack-en]
2025-09-17 00:14:11.575144 | controller | ok: Nothing to do
2025-09-17 00:14:11.588157 | 
2025-09-17 00:14:11.588310 | TASK [Ensure controller directory exists]
2025-09-17 00:14:11.975091 | controller | changed
2025-09-17 00:14:11.983119 | 
2025-09-17 00:14:11.983452 | TASK [Install container runtime]
2025-09-17 00:14:12.026764 | controller | ok
2025-09-17 00:14:12.068568 | 
2025-09-17 00:14:12.068701 | LOOP [ensure-podman : Find distribution installation]
2025-09-17 00:14:12.097490 | controller | ok: "/var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-17 00:14:12.104491 | controller | included: /var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-17 00:14:12.110926 | 
2025-09-17 00:14:12.110993 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-17 00:15:26.855097 | controller | changed
2025-09-17 00:15:26.869177 | 
2025-09-17 00:15:26.869464 | TASK [ensure-podman : Fetch podman version]
2025-09-17 00:15:27.625537 | controller | Client:       Podman Engine
2025-09-17 00:15:27.625619 | controller | Version:      4.6.2
2025-09-17 00:15:27.625649 | controller | API Version:  4.6.2
2025-09-17 00:15:27.625676 | controller | Go Version:   go1.19.12
2025-09-17 00:15:27.625712 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:15:27.625739 | controller | OS/Arch:      linux/amd64
2025-09-17 00:15:28.023102 | controller | ok: Runtime: 0:00:00.213346
2025-09-17 00:15:28.038075 | 
2025-09-17 00:15:28.038274 | TASK [ensure-podman : Print podman version installed]
2025-09-17 00:15:28.079148 | Podman version: Client:       Podman Engine
2025-09-17 00:15:28.079434 | Version:      4.6.2
2025-09-17 00:15:28.079494 | API Version:  4.6.2
2025-09-17 00:15:28.079537 | Go Version:   go1.19.12
2025-09-17 00:15:28.079592 | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:15:28.079634 | OS/Arch:      linux/amd64
2025-09-17 00:15:28.092180 | 
2025-09-17 00:15:28.092339 | TASK [ensure-podman : Validate podman engine]
2025-09-17 00:15:28.230092 | controller | skipping: Conditional result was False
2025-09-17 00:15:28.239514 | 
2025-09-17 00:15:28.239612 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-17 00:15:28.265930 | controller | skipping: Conditional result was False
2025-09-17 00:15:28.282852 | 
2025-09-17 00:15:28.282948 | TASK [Ensure python3.8 is present]
2025-09-17 00:15:28.309435 | controller | skipping: Conditional result was False
2025-09-17 00:15:28.318991 | 
2025-09-17 00:15:28.319095 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-17 00:15:28.353633 | controller | ok
2025-09-17 00:15:28.383398 | 
2025-09-17 00:15:28.383492 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-17 00:15:32.100844 | controller | ok: Nothing to do
2025-09-17 00:15:32.113868 | 
2025-09-17 00:15:32.114003 | TASK [our-ensure-python : Also install python3-devel]
2025-09-17 00:15:45.134201 | controller | changed
2025-09-17 00:15:45.158203 | 
2025-09-17 00:15:45.158338 | TASK [Run ensure-virtualenv role]
2025-09-17 00:15:45.181054 | controller | ok
2025-09-17 00:15:45.208869 | 
2025-09-17 00:15:45.208970 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-17 00:15:45.571891 | controller | /usr/bin/virtualenv
2025-09-17 00:15:45.837613 | controller | ok: Runtime: 0:00:00.004813
2025-09-17 00:15:45.850318 | 
2025-09-17 00:15:45.850467 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-17 00:15:45.878347 | controller | skipping: Conditional result was False
2025-09-17 00:15:45.878685 | controller | ok: All items complete
2025-09-17 00:15:45.878723 | 
2025-09-17 00:15:45.936951 | 
2025-09-17 00:15:45.937116 | TASK [Find the full path of the Python interpreter]
2025-09-17 00:15:46.367608 | controller | /usr/bin/python3
2025-09-17 00:15:46.561061 | controller | ok
2025-09-17 00:15:46.573199 | 
2025-09-17 00:15:46.573330 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-17 00:15:48.096189 | controller | created virtual environment CPython3.11.0.final.0-64 in 744ms
2025-09-17 00:15:48.151412 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-17 00:15:48.152189 | 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-09-17 00:15:48.152339 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-17 00:15:48.152366 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-17 00:15:48.232873 | controller | changed
2025-09-17 00:15:48.245527 | 
2025-09-17 00:15:48.245651 | TASK [Set selinux package]
2025-09-17 00:15:48.284292 | controller | ok
2025-09-17 00:15:48.295265 | 
2025-09-17 00:15:48.295431 | TASK [Set selinux package (Fedora)]
2025-09-17 00:15:48.343266 | controller | ok
2025-09-17 00:15:48.354273 | 
2025-09-17 00:15:48.354405 | TASK [Install selinux into virtualenv]
2025-09-17 00:15:50.959709 | controller | Collecting selinux-please-lie-to-me
2025-09-17 00:15:51.048741 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-17 00:15:51.580043 | controller | Collecting setuptools<50.0.0
2025-09-17 00:15:51.593707 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-17 00:15:51.722552 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.5 MB/s eta 0:00:00
2025-09-17 00:15:51.872570 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-17 00:15:51.872887 | controller |   Attempting uninstall: setuptools
2025-09-17 00:15:51.877796 | controller |     Found existing installation: setuptools 62.6.0
2025-09-17 00:15:51.989040 | controller |     Uninstalling setuptools-62.6.0:
2025-09-17 00:15:52.004154 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-17 00:15:52.752048 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-17 00:15:52.962135 | controller |
2025-09-17 00:15:53.169886 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:15:53.169937 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:15:53.527048 | controller | ok: Runtime: 0:00:04.342231
2025-09-17 00:15:53.538500 | 
2025-09-17 00:15:53.538632 | TASK [Install pytest-forked into virtualenv]
2025-09-17 00:15:54.977692 | controller | Collecting pytest-forked
2025-09-17 00:15:55.070934 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-17 00:15:55.127797 | controller | Collecting py
2025-09-17 00:15:55.142130 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-17 00:15:55.181192 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.8 MB/s eta 0:00:00
2025-09-17 00:15:55.357033 | controller | Collecting pytest>=3.10
2025-09-17 00:15:55.371442 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-17 00:15:55.466615 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 3.9 MB/s eta 0:00:00
2025-09-17 00:15:55.526048 | controller | Collecting iniconfig>=1
2025-09-17 00:15:55.540151 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-17 00:15:55.608387 | controller | Collecting packaging>=20
2025-09-17 00:15:55.622300 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-17 00:15:55.642652 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.4 MB/s eta 0:00:00
2025-09-17 00:15:55.688809 | controller | Collecting pluggy<2,>=1.5
2025-09-17 00:15:55.702657 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-17 00:15:55.780625 | controller | Collecting pygments>=2.7.2
2025-09-17 00:15:55.794399 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-17 00:15:56.048558 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 4.9 MB/s eta 0:00:00
2025-09-17 00:15:56.183935 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-17 00:15:58.393275 | 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-09-17 00:15:58.409742 | controller |
2025-09-17 00:15:58.584123 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:15:58.584168 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:15:58.701236 | controller | ok: Runtime: 0:00:04.331306
2025-09-17 00:15:58.713507 | 
2025-09-17 00:15:58.713636 | TASK [Update pip]
2025-09-17 00:15:59.819724 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-17 00:16:00.116600 | controller | Collecting pip
2025-09-17 00:16:00.221232 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-17 00:16:00.391227 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.7 MB/s eta 0:00:00
2025-09-17 00:16:00.534129 | controller | Installing collected packages: pip
2025-09-17 00:16:00.534540 | controller |   Attempting uninstall: pip
2025-09-17 00:16:00.539065 | controller |     Found existing installation: pip 22.2.2
2025-09-17 00:16:00.797314 | controller |     Uninstalling pip-22.2.2:
2025-09-17 00:16:00.834858 | controller |       Successfully uninstalled pip-22.2.2
2025-09-17 00:16:02.626859 | controller | Successfully installed pip-25.2
2025-09-17 00:16:03.369757 | controller | ok: Runtime: 0:00:03.610805
2025-09-17 00:16:03.382078 | 
2025-09-17 00:16:03.382208 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-17 00:16:03.924030 | controller | changed
2025-09-17 00:16:03.936079 | 
2025-09-17 00:16:03.936563 | TASK [Install ansible into virtualenv]
2025-09-17 00:16:05.006041 | controller | Processing ./src/github.com/ansible/ansible
2025-09-17 00:16:05.012603 | controller |   Installing build dependencies: started
2025-09-17 00:16:06.849585 | controller |   Installing build dependencies: finished with status 'done'
2025-09-17 00:16:08.358889 | controller |   Getting requirements to build wheel: started
2025-09-17 00:16:08.358952 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-17 00:16:08.359152 | controller |   Preparing metadata (pyproject.toml): started
2025-09-17 00:16:09.269893 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-17 00:16:09.274644 | 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-09-17 00:16:09.279459 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-17 00:16:09.584925 | controller | ERROR
2025-09-17 00:16:09.585256 | controller | {
2025-09-17 00:16:09.585321 | controller |   "delta": "0:00:05.041938",
2025-09-17 00:16:09.585363 | controller |   "end": "2025-09-17 00:16:09.427603",
2025-09-17 00:16:09.585402 | controller |   "msg": "non-zero return code",
2025-09-17 00:16:09.585456 | controller |   "rc": 1,
2025-09-17 00:16:09.585494 | controller |   "start": "2025-09-17 00:16:04.385665"
2025-09-17 00:16:09.585530 | controller | }
failure
2025-09-17 00:16:09.588400 | 
2025-09-17 00:16:09.588505 | PLAY RECAP
2025-09-17 00:16:09.588588 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-17 00:16:09.588632 | 
2025-09-17 00:16:09.721460 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:16:09.722429 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:16:10.262475 | 
2025-09-17 00:16:10.262585 | PLAY [all]
2025-09-17 00:16:10.284489 | 
2025-09-17 00:16:10.284593 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-17 00:16:11.043595 | controller | changed: non-zero return code
2025-09-17 00:16:11.057497 | 
2025-09-17 00:16:11.057726 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-17 00:16:11.088814 | controller | skipping: Conditional result was False
2025-09-17 00:16:11.104356 | 
2025-09-17 00:16:11.104513 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-17 00:16:11.148016 | 
2025-09-17 00:16:11.148284 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-17 00:16:11.200313 | 
2025-09-17 00:16:11.200602 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-17 00:16:11.229077 | controller | skipping: Conditional result was False
2025-09-17 00:16:11.243607 | 
2025-09-17 00:16:11.243794 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-17 00:16:11.288080 | 
2025-09-17 00:16:11.288339 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-17 00:16:11.316367 | controller | skipping: Conditional result was False
2025-09-17 00:16:11.330756 | 
2025-09-17 00:16:11.330912 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-17 00:16:11.359446 | controller | skipping: Conditional result was False
2025-09-17 00:16:11.373570 | 
2025-09-17 00:16:11.373774 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-17 00:16:11.402018 | controller | skipping: Conditional result was False
2025-09-17 00:16:11.450654 | 
2025-09-17 00:16:11.450822 | PLAY RECAP
2025-09-17 00:16:11.450895 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:16:11.450927 | 
2025-09-17 00:16:11.559425 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:16:11.560463 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-17 00:16:12.137510 | 
2025-09-17 00:16:12.137624 | PLAY [all:!appliance*]
2025-09-17 00:16:12.158478 | 
2025-09-17 00:16:12.158560 | TASK [unregister the node]
2025-09-17 00:16:12.285035 | controller | skipping: Conditional result was False
2025-09-17 00:16:12.302244 | 
2025-09-17 00:16:12.302445 | TASK [include_role : fetch-output]
2025-09-17 00:16:12.346573 | controller | ok
2025-09-17 00:16:12.385437 | 
2025-09-17 00:16:12.385617 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-17 00:16:12.442438 | controller | skipping: Conditional result was False
2025-09-17 00:16:12.450831 | 
2025-09-17 00:16:12.450987 | TASK [fetch-output : Set log path for single node]
2025-09-17 00:16:12.483820 | controller | ok
2025-09-17 00:16:12.490868 | 
2025-09-17 00:16:12.490953 | LOOP [fetch-output : Ensure local output dirs]
2025-09-17 00:16:12.881202 | controller -> localhost | ok: "/var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/logs"
2025-09-17 00:16:13.164901 | controller -> localhost | changed: "/var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/artifacts"
2025-09-17 00:16:13.447366 | controller -> localhost | changed: "/var/lib/zuul/builds/81a3860b72fe46c6857133c121b55daf/work/docs"
2025-09-17 00:16:13.475466 | 
2025-09-17 00:16:13.475698 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-17 00:16:14.699919 | controller | changed:
2025-09-17 00:16:14.700286 | controller | .d..t...... ./
2025-09-17 00:16:14.700360 | controller | cd+++++++++ controller/
2025-09-17 00:16:14.700451 | controller | changed: All items complete
2025-09-17 00:16:14.700505 | 
2025-09-17 00:16:15.771440 | controller | changed: .d..t...... ./
2025-09-17 00:16:16.868528 | controller | changed: .d..t...... ./
2025-09-17 00:16:16.897621 | 
2025-09-17 00:16:16.897831 | TASK [include_role : fetch-output-openshift]
2025-09-17 00:16:16.926138 | controller | skipping: Conditional result was False
2025-09-17 00:16:16.943108 | 
2025-09-17 00:16:16.943275 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-17 00:16:16.985646 | controller | skipping: Conditional result was False
2025-09-17 00:16:16.997269 | controller | skipping: Conditional result was False
2025-09-17 00:16:17.033747 | 
2025-09-17 00:16:17.033818 | PLAY [localhost]
2025-09-17 00:16:17.045979 | 
2025-09-17 00:16:17.046044 | TASK [Run Zuul manifest role]
2025-09-17 00:16:17.073864 | localhost | ok
2025-09-17 00:16:17.086878 | 
2025-09-17 00:16:17.086942 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-17 00:16:17.500217 | localhost | changed
2025-09-17 00:16:17.509951 | 
2025-09-17 00:16:17.510063 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-17 00:16:17.556347 | localhost | ok
2025-09-17 00:16:17.568500 | 
2025-09-17 00:16:17.568593 | TASK [Set zuul-log-path fact]
2025-09-17 00:16:17.592537 | localhost | ok
2025-09-17 00:16:17.612412 | 
2025-09-17 00:16:17.612544 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:16:17.656015 | localhost | ok
2025-09-17 00:16:17.670029 | 
2025-09-17 00:16:17.670125 | LOOP [Run upload-logs-swift role]
2025-09-17 00:16:17.707467 | localhost | Output suppressed because no_log was given
2025-09-17 00:16:17.747084 | 
2025-09-17 00:16:17.747307 | TASK [Set zuul-log-path fact]
2025-09-17 00:16:17.785239 | localhost | skipping: Conditional result was False
2025-09-17 00:16:17.793050 | 
2025-09-17 00:16:17.793147 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-17 00:16:18.198217 | localhost -> localhost | ok: Runtime: 0:00:00.004899
2025-09-17 00:16:18.221813 | 
2025-09-17 00:16:18.222096 | TASK [upload-logs-swift : Upload logs to swift]