2025-10-22 00:17:22.211123 | Job console starting...
2025-10-22 00:17:22.222645 | Updating repositories
2025-10-22 00:17:22.353440 | Preparing job workspace
2025-10-22 00:17:26.123644 | Running Ansible setup...
2025-10-22 00:17:32.571936 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-22 00:17:33.214847 | 
2025-10-22 00:17:33.214986 | PLAY [localhost]
2025-10-22 00:17:33.223786 | 
2025-10-22 00:17:33.223862 | TASK [Gathering Facts]
2025-10-22 00:17:34.312558 | localhost | ok
2025-10-22 00:17:34.341613 | 
2025-10-22 00:17:34.341876 | TASK [Setup log path fact]
2025-10-22 00:17:34.363588 | localhost | ok
2025-10-22 00:17:34.381309 | 
2025-10-22 00:17:34.381475 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-22 00:17:34.423545 | localhost | ok
2025-10-22 00:17:34.435099 | 
2025-10-22 00:17:34.435312 | TASK [emit-job-header : Print job information]
2025-10-22 00:17:34.490897 | # Job Information
2025-10-22 00:17:34.491179 | Ansible Version: 2.15.12
2025-10-22 00:17:34.491244 | Job: ansible-test-sanity-docker-milestone
2025-10-22 00:17:34.491289 | Pipeline: periodic
2025-10-22 00:17:34.491329 | Executor: ze02.softwarefactory-project.io
2025-10-22 00:17:34.491368 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-22 00:17:34.491413 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/6a8/ansible/6a88e59054ef48d6a61295e35bcc8973/
2025-10-22 00:17:34.491455 | Event ID: 29cce05ecf284232acebc18c8d35e894
2025-10-22 00:17:34.499459 | 
2025-10-22 00:17:34.499597 | LOOP [emit-job-header : Print node information]
2025-10-22 00:17:34.609047 | localhost | ok:
2025-10-22 00:17:34.609267 | localhost | # Node Information
2025-10-22 00:17:34.609301 | localhost | Inventory Hostname: controller
2025-10-22 00:17:34.609329 | localhost | Hostname: ip-172-16-200-138
2025-10-22 00:17:34.609352 | localhost | Username: zuul-worker
2025-10-22 00:17:34.609378 | localhost | Distro: Fedora 37
2025-10-22 00:17:34.609401 | localhost | Provider: ansible-us-east-2
2025-10-22 00:17:34.609424 | localhost | Region: us-east-2
2025-10-22 00:17:34.609445 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-22 00:17:34.609467 | localhost | Product Name: t3.small
2025-10-22 00:17:34.609489 | localhost | Interface IP: 3.129.44.170
2025-10-22 00:17:34.627838 | 
2025-10-22 00:17:34.628073 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-22 00:17:35.083622 | localhost -> localhost | changed
2025-10-22 00:17:35.091601 | 
2025-10-22 00:17:35.091801 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-22 00:17:36.016112 | localhost -> localhost | changed
2025-10-22 00:17:36.061849 | 
2025-10-22 00:17:36.061982 | PLAY [all:!appliance*]
2025-10-22 00:17:36.086784 | 
2025-10-22 00:17:36.086934 | TASK [include_role : start-zuul-console]
2025-10-22 00:17:36.111794 | controller | ok
2025-10-22 00:17:36.133433 | 
2025-10-22 00:17:36.133559 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-22 00:17:36.846334 | controller | ok
2025-10-22 00:17:36.870813 | 
2025-10-22 00:17:36.870956 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-22 00:17:42.274493 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-22 00:17:42.286153 | 
2025-10-22 00:17:42.286303 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-22 00:17:42.429224 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.437183 | 
2025-10-22 00:17:42.437297 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-22 00:17:42.473060 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.480868 | 
2025-10-22 00:17:42.480962 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-22 00:17:42.516951 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.530642 | 
2025-10-22 00:17:42.530857 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-22 00:17:42.558992 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.573170 | 
2025-10-22 00:17:42.573379 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-22 00:17:42.601584 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.615168 | 
2025-10-22 00:17:42.615339 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-22 00:17:42.643230 | controller | skipping: Conditional result was False
2025-10-22 00:17:42.658828 | 
2025-10-22 00:17:42.659008 | TASK [Disable Fedora Modular]
2025-10-22 00:17:43.510930 | controller | changed
2025-10-22 00:17:43.517084 | 
2025-10-22 00:17:43.517188 | TASK [Enable EPEL]
2025-10-22 00:17:43.543244 | controller | skipping: Conditional result was False
2025-10-22 00:17:43.551232 | 
2025-10-22 00:17:43.551300 | TASK [Register the RHEL node]
2025-10-22 00:17:43.756867 | 
2025-10-22 00:17:43.757078 | TASK [Show the subscription-manager status]
2025-10-22 00:17:43.898286 | controller | skipping: Conditional result was False
2025-10-22 00:17:43.906548 | 
2025-10-22 00:17:43.906684 | TASK [Enable EPEL on RHEL]
2025-10-22 00:17:44.050794 | controller | skipping: Conditional result was False
2025-10-22 00:17:44.058229 | 
2025-10-22 00:17:44.058337 | TASK [Install git and tox]
2025-10-22 00:19:26.373467 | controller | changed
2025-10-22 00:19:26.394803 | 
2025-10-22 00:19:26.395002 | TASK [include_role : prepare-workspace]
2025-10-22 00:19:26.434777 | controller | ok
2025-10-22 00:19:26.464079 | 
2025-10-22 00:19:26.464233 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-22 00:19:26.983020 | controller | ok
2025-10-22 00:19:26.990043 | 
2025-10-22 00:19:26.990139 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-22 00:19:39.932571 | controller | Output suppressed because no_log was given
2025-10-22 00:19:39.950387 | 
2025-10-22 00:19:39.950571 | TASK [include_role : prepare-workspace-openshift]
2025-10-22 00:19:39.979447 | controller | skipping: Conditional result was False
2025-10-22 00:19:40.049936 | 
2025-10-22 00:19:40.050113 | PLAY [all:!appliance]
2025-10-22 00:19:40.067093 | 
2025-10-22 00:19:40.067156 | TASK [Run add-build-sshkey role (RSA)]
2025-10-22 00:19:40.097807 | controller | ok
2025-10-22 00:19:40.113553 | 
2025-10-22 00:19:40.113620 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-22 00:19:40.372262 | controller -> localhost | ok
2025-10-22 00:19:40.379639 | 
2025-10-22 00:19:40.379727 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-22 00:19:40.410506 | controller | ok
2025-10-22 00:19:40.424851 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-22 00:19:40.430686 | 
2025-10-22 00:19:40.430746 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-22 00:19:41.036271 | controller -> localhost | Generating public/private rsa key pair.
2025-10-22 00:19:41.036565 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_rsa.
2025-10-22 00:19:41.036593 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_rsa.pub.
2025-10-22 00:19:41.036615 | controller -> localhost | The key fingerprint is:
2025-10-22 00:19:41.036634 | controller -> localhost | SHA256:u7cSEgjIHgh60U8RYwF/Pc06jDEC7Z+6SqiR2x+hsak zuul-build-sshkey
2025-10-22 00:19:41.036656 | controller -> localhost | The key's randomart image is:
2025-10-22 00:19:41.036741 | controller -> localhost | +---[RSA 2048]----+
2025-10-22 00:19:41.036763 | controller -> localhost | |=...oo*+         |
2025-10-22 00:19:41.036782 | controller -> localhost | |+o...+o. . o     |
2025-10-22 00:19:41.036801 | controller -> localhost | |o o. =o + o o    |
2025-10-22 00:19:41.036827 | controller -> localhost | | o  . +o = o     |
2025-10-22 00:19:41.036845 | controller -> localhost | |  . .  oS.+      |
2025-10-22 00:19:41.036878 | controller -> localhost | | . * .. +. .     |
2025-10-22 00:19:41.036901 | controller -> localhost | |o = o  o..       |
2025-10-22 00:19:41.036920 | controller -> localhost | | * . .. ...      |
2025-10-22 00:19:41.036937 | controller -> localhost | |E ..o....o..     |
2025-10-22 00:19:41.036957 | controller -> localhost | +----[SHA256]-----+
2025-10-22 00:19:41.037016 | controller -> localhost | ok: Runtime: 0:00:00.134136
2025-10-22 00:19:41.044256 | 
2025-10-22 00:19:41.044319 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-22 00:19:41.075845 | controller | ok
2025-10-22 00:19:41.086149 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-22 00:19:41.094901 | 
2025-10-22 00:19:41.094961 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-22 00:19:41.120284 | controller | skipping: Conditional result was False
2025-10-22 00:19:41.127101 | 
2025-10-22 00:19:41.127164 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-22 00:19:41.830769 | controller | changed
2025-10-22 00:19:41.843294 | 
2025-10-22 00:19:41.843442 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-22 00:19:42.210694 | controller | ok
2025-10-22 00:19:42.223361 | 
2025-10-22 00:19:42.223547 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-22 00:19:43.543417 | controller | changed
2025-10-22 00:19:43.558489 | 
2025-10-22 00:19:43.558691 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-22 00:19:45.115417 | controller | changed
2025-10-22 00:19:45.128843 | 
2025-10-22 00:19:45.128982 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-22 00:19:45.167755 | controller | skipping: Conditional result was False
2025-10-22 00:19:45.194083 | 
2025-10-22 00:19:45.194439 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-22 00:19:45.672874 | controller -> localhost | changed
2025-10-22 00:19:45.686946 | 
2025-10-22 00:19:45.687034 | TASK [add-build-sshkey : Add back temp key]
2025-10-22 00:19:46.049591 | controller -> localhost | Identity added: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_rsa (zuul-build-sshkey)
2025-10-22 00:19:46.049917 | controller -> localhost | ok: Runtime: 0:00:00.011947
2025-10-22 00:19:46.057831 | 
2025-10-22 00:19:46.057899 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-22 00:19:46.616078 | controller | ok
2025-10-22 00:19:46.629061 | 
2025-10-22 00:19:46.629178 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-22 00:19:46.658580 | controller | skipping: Conditional result was False
2025-10-22 00:19:46.681472 | 
2025-10-22 00:19:46.681598 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-22 00:19:46.710589 | controller | ok
2025-10-22 00:19:46.737512 | 
2025-10-22 00:19:46.737775 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-22 00:19:47.027972 | controller -> localhost | ok
2025-10-22 00:19:47.036176 | 
2025-10-22 00:19:47.036264 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-22 00:19:47.069365 | controller | ok
2025-10-22 00:19:47.082490 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-22 00:19:47.089773 | 
2025-10-22 00:19:47.089841 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-22 00:19:47.421376 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-22 00:19:47.421751 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_ecdsa.
2025-10-22 00:19:47.421795 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_ecdsa.pub.
2025-10-22 00:19:47.421838 | controller -> localhost | The key fingerprint is:
2025-10-22 00:19:47.421866 | controller -> localhost | SHA256:nv7Uot9eYW/Rixb1WaPHPZFZnBOjWDlJPlJVLC46rgc zuul-build-sshkey
2025-10-22 00:19:47.421894 | controller -> localhost | The key's randomart image is:
2025-10-22 00:19:47.421920 | controller -> localhost | +---[ECDSA 521]---+
2025-10-22 00:19:47.421946 | controller -> localhost | |            .++**|
2025-10-22 00:19:47.421971 | controller -> localhost | |            =+ooB|
2025-10-22 00:19:47.421995 | controller -> localhost | |           o =.Bo|
2025-10-22 00:19:47.422019 | controller -> localhost | |            o * O|
2025-10-22 00:19:47.422042 | controller -> localhost | |        S  . +o*+|
2025-10-22 00:19:47.422066 | controller -> localhost | |       .E.o. .+o+|
2025-10-22 00:19:47.422098 | controller -> localhost | |        ooo..o..o|
2025-10-22 00:19:47.422123 | controller -> localhost | |       . ooo.. . |
2025-10-22 00:19:47.422146 | controller -> localhost | |        +=o.o    |
2025-10-22 00:19:47.422170 | controller -> localhost | +----[SHA256]-----+
2025-10-22 00:19:47.422248 | controller -> localhost | ok: Runtime: 0:00:00.016838
2025-10-22 00:19:47.432966 | 
2025-10-22 00:19:47.433063 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-22 00:19:47.481162 | controller | ok
2025-10-22 00:19:47.492840 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-22 00:19:47.505109 | 
2025-10-22 00:19:47.505180 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-22 00:19:47.540973 | controller | skipping: Conditional result was False
2025-10-22 00:19:47.548481 | 
2025-10-22 00:19:47.548558 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-22 00:19:48.026313 | controller | changed
2025-10-22 00:19:48.039735 | 
2025-10-22 00:19:48.039887 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-22 00:19:48.389359 | controller | ok
2025-10-22 00:19:48.395074 | 
2025-10-22 00:19:48.395147 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-22 00:19:49.689138 | controller | changed
2025-10-22 00:19:49.698970 | 
2025-10-22 00:19:49.699130 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-22 00:19:50.955813 | controller | changed
2025-10-22 00:19:50.961441 | 
2025-10-22 00:19:50.961506 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-22 00:19:50.990928 | controller | skipping: Conditional result was False
2025-10-22 00:19:51.008232 | 
2025-10-22 00:19:51.008392 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-22 00:19:51.295375 | controller -> localhost | changed
2025-10-22 00:19:51.307604 | 
2025-10-22 00:19:51.307707 | TASK [add-build-sshkey : Add back temp key]
2025-10-22 00:19:51.632964 | controller -> localhost | Identity added: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/6a88e59054ef48d6a61295e35bcc8973_id_ecdsa (zuul-build-sshkey)
2025-10-22 00:19:51.633422 | controller -> localhost | ok: Runtime: 0:00:00.015683
2025-10-22 00:19:51.706013 | 
2025-10-22 00:19:51.706188 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-22 00:19:52.054733 | controller | ok
2025-10-22 00:19:52.061660 | 
2025-10-22 00:19:52.061784 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-22 00:19:52.099316 | controller | skipping: Conditional result was False
2025-10-22 00:19:52.111301 | 
2025-10-22 00:19:52.111370 | TASK [include_role : remove-zuul-sshkey]
2025-10-22 00:19:52.137064 | controller | skipping: Conditional result was False
2025-10-22 00:19:52.143675 | 
2025-10-22 00:19:52.143739 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-22 00:19:52.512839 | controller | ok: "logs"
2025-10-22 00:19:52.513121 | controller | ok: All items complete
2025-10-22 00:19:52.513148 | 
2025-10-22 00:19:52.894840 | controller | ok: "artifacts"
2025-10-22 00:19:53.295176 | controller | ok: "docs"
2025-10-22 00:19:53.319375 | 
2025-10-22 00:19:53.319779 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-22 00:19:53.650924 | controller | changed: "logs"
2025-10-22 00:19:53.952040 | controller | changed: "artifacts"
2025-10-22 00:19:54.290045 | controller | changed: "docs"
2025-10-22 00:19:54.348505 | 
2025-10-22 00:19:54.348718 | PLAY RECAP
2025-10-22 00:19:54.348794 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-22 00:19:54.348834 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-22 00:19:54.348859 | 
2025-10-22 00:19:54.546850 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-22 00:19:54.547979 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-22 00:19:55.133794 | 
2025-10-22 00:19:55.133975 | PLAY [all]
2025-10-22 00:19:55.159189 | 
2025-10-22 00:19:55.159383 | TASK [Install binary dependencies]
2025-10-22 00:19:55.224365 | controller | ok
2025-10-22 00:19:55.248538 | 
2025-10-22 00:19:55.248713 | TASK [bindep : Include find tasks]
2025-10-22 00:19:55.282764 | controller | ok
2025-10-22 00:19:55.295019 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-22 00:19:55.301393 | 
2025-10-22 00:19:55.301461 | TASK [bindep : Look for bindep.txt]
2025-10-22 00:19:55.843340 | controller | ok
2025-10-22 00:19:55.852553 | 
2025-10-22 00:19:55.852649 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:19:55.888985 | controller | skipping: Conditional result was False
2025-10-22 00:19:55.897556 | 
2025-10-22 00:19:55.897642 | TASK [bindep : Look for other-requirements.txt]
2025-10-22 00:19:56.231029 | controller | ok
2025-10-22 00:19:56.239053 | 
2025-10-22 00:19:56.239151 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:19:56.265370 | controller | skipping: Conditional result was False
2025-10-22 00:19:56.275333 | 
2025-10-22 00:19:56.275433 | TASK [bindep : Look for bindep fallback file]
2025-10-22 00:19:56.317644 | controller | skipping: Conditional result was False
2025-10-22 00:19:56.328606 | 
2025-10-22 00:19:56.328752 | TASK [bindep : Define bindep_file fact]
2025-10-22 00:19:56.366415 | controller | skipping: Conditional result was False
2025-10-22 00:19:56.375901 | 
2025-10-22 00:19:56.376008 | TASK [bindep : Include bindep tasks]
2025-10-22 00:19:56.413224 | controller | skipping: Conditional result was False
2025-10-22 00:19:56.422024 | 
2025-10-22 00:19:56.422096 | TASK [bindep : Include install tasks]
2025-10-22 00:19:56.457628 | controller | skipping: Conditional result was False
2025-10-22 00:19:56.465226 | 
2025-10-22 00:19:56.465297 | LOOP [bindep : Include package tasks]
2025-10-22 00:19:56.522105 | 
2025-10-22 00:19:56.522299 | TASK [Run test-setup role]
2025-10-22 00:19:56.542903 | controller | ok
2025-10-22 00:19:56.563186 | 
2025-10-22 00:19:56.563269 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-22 00:19:56.890811 | controller | ok
2025-10-22 00:19:56.899650 | 
2025-10-22 00:19:56.899771 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-22 00:19:57.050226 | controller | skipping: Conditional result was False
2025-10-22 00:19:57.106265 | 
2025-10-22 00:19:57.106434 | PLAY RECAP
2025-10-22 00:19:57.106505 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-22 00:19:57.106567 | 
2025-10-22 00:19:57.278597 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-22 00:19:57.279558 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-22 00:19:57.844013 | 
2025-10-22 00:19:57.844171 | PLAY [controller]
2025-10-22 00:19:57.863484 | 
2025-10-22 00:19:57.863557 | TASK [Create the /root directory]
2025-10-22 00:19:58.621016 | controller | ok
2025-10-22 00:19:58.635792 | 
2025-10-22 00:19:58.636105 | TASK [Install glibc-langpack-en]
2025-10-22 00:20:08.110734 | controller | ok: Nothing to do
2025-10-22 00:20:08.119205 | 
2025-10-22 00:20:08.119303 | TASK [Ensure controller directory exists]
2025-10-22 00:20:08.551155 | controller | changed
2025-10-22 00:20:08.558912 | 
2025-10-22 00:20:08.559002 | TASK [Install container runtime]
2025-10-22 00:20:08.614424 | controller | ok
2025-10-22 00:20:08.664683 | 
2025-10-22 00:20:08.664861 | LOOP [ensure-podman : Find distribution installation]
2025-10-22 00:20:08.698564 | controller | ok: "/var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-22 00:20:08.707700 | controller | included: /var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-22 00:20:08.714125 | 
2025-10-22 00:20:08.714189 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-22 00:21:40.874113 | controller | changed
2025-10-22 00:21:40.888107 | 
2025-10-22 00:21:40.888244 | TASK [ensure-podman : Fetch podman version]
2025-10-22 00:21:41.758835 | controller | Client:       Podman Engine
2025-10-22 00:21:41.789671 | controller | Version:      4.6.2
2025-10-22 00:21:41.789718 | controller | API Version:  4.6.2
2025-10-22 00:21:41.789727 | controller | Go Version:   go1.19.12
2025-10-22 00:21:41.789747 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-22 00:21:41.789756 | controller | OS/Arch:      linux/amd64
2025-10-22 00:21:42.033483 | controller | ok: Runtime: 0:00:00.274730
2025-10-22 00:21:42.047907 | 
2025-10-22 00:21:42.048090 | TASK [ensure-podman : Print podman version installed]
2025-10-22 00:21:42.098586 | Podman version: Client:       Podman Engine
2025-10-22 00:21:42.098915 | Version:      4.6.2
2025-10-22 00:21:42.098984 | API Version:  4.6.2
2025-10-22 00:21:42.099034 | Go Version:   go1.19.12
2025-10-22 00:21:42.099078 | Built:        Mon Aug 28 19:38:31 2023
2025-10-22 00:21:42.099122 | OS/Arch:      linux/amd64
2025-10-22 00:21:42.112096 | 
2025-10-22 00:21:42.112277 | TASK [ensure-podman : Validate podman engine]
2025-10-22 00:21:42.498092 | controller | skipping: Conditional result was False
2025-10-22 00:21:42.512295 | 
2025-10-22 00:21:42.512499 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-22 00:21:42.539963 | controller | skipping: Conditional result was False
2025-10-22 00:21:42.564888 | 
2025-10-22 00:21:42.565053 | TASK [Ensure python3.8 is present]
2025-10-22 00:21:42.591927 | controller | skipping: Conditional result was False
2025-10-22 00:21:42.605338 | 
2025-10-22 00:21:42.605482 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-22 00:21:42.634319 | controller | ok
2025-10-22 00:21:42.667137 | 
2025-10-22 00:21:42.667312 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-22 00:21:46.584265 | controller | ok: Nothing to do
2025-10-22 00:21:46.593284 | 
2025-10-22 00:21:46.593420 | TASK [our-ensure-python : Also install python3-devel]
2025-10-22 00:22:02.409454 | controller | changed
2025-10-22 00:22:02.420919 | 
2025-10-22 00:22:02.420989 | TASK [Run ensure-virtualenv role]
2025-10-22 00:22:02.442595 | controller | ok
2025-10-22 00:22:02.474876 | 
2025-10-22 00:22:02.475052 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-22 00:22:03.385262 | controller | /usr/bin/virtualenv
2025-10-22 00:22:03.625271 | controller | ok: Runtime: 0:00:00.006221
2025-10-22 00:22:03.639974 | 
2025-10-22 00:22:03.640144 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-22 00:22:03.681299 | controller | skipping: Conditional result was False
2025-10-22 00:22:03.681813 | controller | ok: All items complete
2025-10-22 00:22:03.681874 | 
2025-10-22 00:22:03.758407 | 
2025-10-22 00:22:03.758616 | TASK [Find the full path of the Python interpreter]
2025-10-22 00:22:04.261284 | controller | /usr/bin/python3
2025-10-22 00:22:04.402855 | controller | ok
2025-10-22 00:22:04.415004 | 
2025-10-22 00:22:04.415144 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-22 00:22:06.450570 | controller | created virtual environment CPython3.11.0.final.0-64 in 803ms
2025-10-22 00:22:06.497383 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-22 00:22:06.497440 | 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-22 00:22:06.497456 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-22 00:22:06.497480 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-22 00:22:06.575452 | controller | changed
2025-10-22 00:22:06.589694 | 
2025-10-22 00:22:06.589898 | TASK [Set selinux package]
2025-10-22 00:22:06.633528 | controller | ok
2025-10-22 00:22:06.645827 | 
2025-10-22 00:22:06.646031 | TASK [Set selinux package (Fedora)]
2025-10-22 00:22:06.703343 | controller | ok
2025-10-22 00:22:06.712533 | 
2025-10-22 00:22:06.712831 | TASK [Install selinux into virtualenv]
2025-10-22 00:22:09.253197 | controller | Collecting selinux-please-lie-to-me
2025-10-22 00:22:09.344167 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-22 00:22:09.866607 | controller | Collecting setuptools<50.0.0
2025-10-22 00:22:09.880084 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-22 00:22:09.953563 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.8 MB/s eta 0:00:00
2025-10-22 00:22:10.104696 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-22 00:22:10.105128 | controller |   Attempting uninstall: setuptools
2025-10-22 00:22:10.110121 | controller |     Found existing installation: setuptools 62.6.0
2025-10-22 00:22:10.222133 | controller |     Uninstalling setuptools-62.6.0:
2025-10-22 00:22:10.237324 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-22 00:22:11.005142 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-22 00:22:11.207897 | controller |
2025-10-22 00:22:11.421257 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-22 00:22:11.421308 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-22 00:22:11.900735 | controller | ok: Runtime: 0:00:04.270682
2025-10-22 00:22:11.913849 | 
2025-10-22 00:22:11.914047 | TASK [Install pytest-forked into virtualenv]
2025-10-22 00:22:13.112635 | controller | Collecting pytest-forked
2025-10-22 00:22:13.204635 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-22 00:22:13.274107 | controller | Collecting py
2025-10-22 00:22:13.289553 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-22 00:22:13.326424 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00
2025-10-22 00:22:13.506141 | controller | Collecting pytest>=3.10
2025-10-22 00:22:13.520744 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-22 00:22:13.569573 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.9 MB/s eta 0:00:00
2025-10-22 00:22:13.653889 | controller | Collecting iniconfig>=1
2025-10-22 00:22:13.668421 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-22 00:22:13.746871 | controller | Collecting packaging>=20
2025-10-22 00:22:13.761237 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-22 00:22:13.770699 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.8 MB/s eta 0:00:00
2025-10-22 00:22:13.829360 | controller | Collecting pluggy<2,>=1.5
2025-10-22 00:22:13.843651 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-22 00:22:13.928180 | controller | Collecting pygments>=2.7.2
2025-10-22 00:22:13.942590 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-22 00:22:13.972596 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 46.7 MB/s eta 0:00:00
2025-10-22 00:22:14.104387 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-22 00:22:16.356512 | 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-22 00:22:16.372847 | controller |
2025-10-22 00:22:16.563487 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-22 00:22:16.563533 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-22 00:22:16.626197 | controller | ok: Runtime: 0:00:04.166057
2025-10-22 00:22:16.637547 | 
2025-10-22 00:22:16.637732 | TASK [Update pip]
2025-10-22 00:22:17.911558 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-22 00:22:18.178017 | controller | Collecting pip
2025-10-22 00:22:18.277481 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-22 00:22:18.492216 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.4 MB/s eta 0:00:00
2025-10-22 00:22:18.656459 | controller | Installing collected packages: pip
2025-10-22 00:22:18.657333 | controller |   Attempting uninstall: pip
2025-10-22 00:22:18.662779 | controller |     Found existing installation: pip 22.2.2
2025-10-22 00:22:18.962600 | controller |     Uninstalling pip-22.2.2:
2025-10-22 00:22:18.992185 | controller |       Successfully uninstalled pip-22.2.2
2025-10-22 00:22:20.717261 | controller | Successfully installed pip-25.2
2025-10-22 00:22:21.284947 | controller | ok: Runtime: 0:00:03.807513
2025-10-22 00:22:21.297426 | 
2025-10-22 00:22:21.297558 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-22 00:22:21.807562 | controller | changed
2025-10-22 00:22:21.820517 | 
2025-10-22 00:22:21.820659 | TASK [Install ansible into virtualenv]
2025-10-22 00:22:22.913458 | controller | Processing ./src/github.com/ansible/ansible
2025-10-22 00:22:22.919911 | controller |   Installing build dependencies: started
2025-10-22 00:22:24.848876 | controller |   Installing build dependencies: finished with status 'done'
2025-10-22 00:22:24.850134 | controller |   Getting requirements to build wheel: started
2025-10-22 00:22:26.362692 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-22 00:22:26.364307 | controller |   Preparing metadata (pyproject.toml): started
2025-10-22 00:22:27.294367 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-22 00:22:27.299318 | 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-22 00:22:27.304004 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-22 00:22:27.981699 | controller | ERROR
2025-10-22 00:22:27.982060 | controller | {
2025-10-22 00:22:27.982123 | controller |   "delta": "0:00:05.193494",
2025-10-22 00:22:27.982165 | controller |   "end": "2025-10-22 00:22:27.456939",
2025-10-22 00:22:27.982203 | controller |   "msg": "non-zero return code",
2025-10-22 00:22:27.982260 | controller |   "rc": 1,
2025-10-22 00:22:27.982296 | controller |   "start": "2025-10-22 00:22:22.263445"
2025-10-22 00:22:27.982329 | controller | }
failure
2025-10-22 00:22:27.985334 | 
2025-10-22 00:22:27.985570 | PLAY RECAP
2025-10-22 00:22:27.985726 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-22 00:22:27.985790 | 
2025-10-22 00:22:28.134448 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-22 00:22:28.136835 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-22 00:22:28.757081 | 
2025-10-22 00:22:28.757202 | PLAY [all]
2025-10-22 00:22:28.778808 | 
2025-10-22 00:22:28.778901 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-22 00:22:29.538467 | controller | changed: non-zero return code
2025-10-22 00:22:29.551360 | 
2025-10-22 00:22:29.551518 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-22 00:22:29.579360 | controller | skipping: Conditional result was False
2025-10-22 00:22:29.597274 | 
2025-10-22 00:22:29.597500 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-22 00:22:29.639418 | 
2025-10-22 00:22:29.639736 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-22 00:22:29.677450 | 
2025-10-22 00:22:29.677753 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-22 00:22:29.694037 | controller | skipping: Conditional result was False
2025-10-22 00:22:29.704389 | 
2025-10-22 00:22:29.704601 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-22 00:22:29.740492 | 
2025-10-22 00:22:29.740759 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-22 00:22:29.756206 | controller | skipping: Conditional result was False
2025-10-22 00:22:29.765392 | 
2025-10-22 00:22:29.765512 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-22 00:22:29.781058 | controller | skipping: Conditional result was False
2025-10-22 00:22:29.789723 | 
2025-10-22 00:22:29.789826 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-22 00:22:29.805058 | controller | skipping: Conditional result was False
2025-10-22 00:22:29.844149 | 
2025-10-22 00:22:29.844277 | PLAY RECAP
2025-10-22 00:22:29.844323 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-22 00:22:29.844343 | 
2025-10-22 00:22:29.966067 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-22 00:22:29.966945 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-22 00:22:30.561596 | 
2025-10-22 00:22:30.561734 | PLAY [all:!appliance*]
2025-10-22 00:22:30.582693 | 
2025-10-22 00:22:30.582794 | TASK [unregister the node]
2025-10-22 00:22:30.727200 | controller | skipping: Conditional result was False
2025-10-22 00:22:30.735912 | 
2025-10-22 00:22:30.736017 | TASK [include_role : fetch-output]
2025-10-22 00:22:30.779936 | controller | ok
2025-10-22 00:22:30.810800 | 
2025-10-22 00:22:30.810945 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-22 00:22:30.888309 | controller | skipping: Conditional result was False
2025-10-22 00:22:30.897291 | 
2025-10-22 00:22:30.897389 | TASK [fetch-output : Set log path for single node]
2025-10-22 00:22:30.942866 | controller | ok
2025-10-22 00:22:30.951810 | 
2025-10-22 00:22:30.951963 | LOOP [fetch-output : Ensure local output dirs]
2025-10-22 00:22:31.423068 | controller -> localhost | ok: "/var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/logs"
2025-10-22 00:22:31.713244 | controller -> localhost | changed: "/var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/artifacts"
2025-10-22 00:22:31.952041 | controller -> localhost | changed: "/var/lib/zuul/builds/6a88e59054ef48d6a61295e35bcc8973/work/docs"
2025-10-22 00:22:31.973020 | 
2025-10-22 00:22:31.973149 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-22 00:22:33.223253 | controller | changed:
2025-10-22 00:22:33.223606 | controller | .d..t...... ./
2025-10-22 00:22:33.223871 | controller | cd+++++++++ controller/
2025-10-22 00:22:33.223974 | controller | changed: All items complete
2025-10-22 00:22:33.224022 | 
2025-10-22 00:22:34.360527 | controller | changed: .d..t...... ./
2025-10-22 00:22:35.436252 | controller | changed: .d..t...... ./
2025-10-22 00:22:35.460588 | 
2025-10-22 00:22:35.460771 | TASK [include_role : fetch-output-openshift]
2025-10-22 00:22:35.486752 | controller | skipping: Conditional result was False
2025-10-22 00:22:35.496351 | 
2025-10-22 00:22:35.496461 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-22 00:22:35.542178 | controller | skipping: Conditional result was False
2025-10-22 00:22:35.556173 | controller | skipping: Conditional result was False
2025-10-22 00:22:35.615957 | 
2025-10-22 00:22:35.616074 | PLAY [localhost]
2025-10-22 00:22:35.633056 | 
2025-10-22 00:22:35.633144 | TASK [Run Zuul manifest role]
2025-10-22 00:22:35.656316 | localhost | ok
2025-10-22 00:22:35.674884 | 
2025-10-22 00:22:35.674983 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-22 00:22:36.131289 | localhost | changed
2025-10-22 00:22:36.142619 | 
2025-10-22 00:22:36.142865 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-22 00:22:36.194446 | localhost | ok
2025-10-22 00:22:36.213337 | 
2025-10-22 00:22:36.213478 | TASK [Set zuul-log-path fact]
2025-10-22 00:22:36.239349 | localhost | ok
2025-10-22 00:22:36.267347 | 
2025-10-22 00:22:36.267447 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-22 00:22:36.311422 | localhost | ok
2025-10-22 00:22:36.331147 | 
2025-10-22 00:22:36.331279 | LOOP [Run upload-logs-swift role]
2025-10-22 00:22:36.379694 | localhost | Output suppressed because no_log was given
2025-10-22 00:22:36.414328 | 
2025-10-22 00:22:36.414464 | TASK [Set zuul-log-path fact]
2025-10-22 00:22:36.450704 | localhost | skipping: Conditional result was False
2025-10-22 00:22:36.458733 | 
2025-10-22 00:22:36.458854 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-22 00:22:36.941696 | localhost -> localhost | ok: Runtime: 0:00:00.006654
2025-10-22 00:22:36.947470 | 
2025-10-22 00:22:36.947554 | TASK [upload-logs-swift : Upload logs to swift]