2025-09-16 00:06:39.261242 | Job console starting...
2025-09-16 00:06:39.274455 | Updating repositories
2025-09-16 00:06:41.676351 | Preparing job workspace
2025-09-16 00:06:50.439077 | Running Ansible setup...
2025-09-16 00:06:57.079644 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-16 00:06:57.734886 | 
2025-09-16 00:06:57.735035 | PLAY [localhost]
2025-09-16 00:06:57.745432 | 
2025-09-16 00:06:57.745524 | TASK [Gathering Facts]
2025-09-16 00:06:58.720648 | localhost | ok
2025-09-16 00:06:58.740086 | 
2025-09-16 00:06:58.740239 | TASK [Setup log path fact]
2025-09-16 00:06:58.760504 | localhost | ok
2025-09-16 00:06:58.779072 | 
2025-09-16 00:06:58.779213 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-16 00:06:58.816841 | localhost | ok
2025-09-16 00:06:58.830373 | 
2025-09-16 00:06:58.830499 | TASK [emit-job-header : Print job information]
2025-09-16 00:06:58.868582 | # Job Information
2025-09-16 00:06:58.868746 | Ansible Version: 2.15.12
2025-09-16 00:06:58.868783 | Job: ansible-test-sanity-docker-milestone
2025-09-16 00:06:58.868807 | Pipeline: periodic
2025-09-16 00:06:58.868826 | Executor: ze03.softwarefactory-project.io
2025-09-16 00:06:58.868847 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-16 00:06:58.868869 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/406/ansible/4064fa99145e452fbd9f8a35ef0a40a0/
2025-09-16 00:06:58.868890 | Event ID: 2918163660474a46b98b92e6629b114f
2025-09-16 00:06:58.872685 | 
2025-09-16 00:06:58.872790 | LOOP [emit-job-header : Print node information]
2025-09-16 00:06:58.990843 | localhost | ok:
2025-09-16 00:06:58.990995 | localhost | # Node Information
2025-09-16 00:06:58.991022 | localhost | Inventory Hostname: controller
2025-09-16 00:06:58.991042 | localhost | Hostname: ip-172-16-86-207
2025-09-16 00:06:58.991061 | localhost | Username: zuul-worker
2025-09-16 00:06:58.991082 | localhost | Distro: Fedora 37
2025-09-16 00:06:58.991100 | localhost | Provider: ansible-us-east-2
2025-09-16 00:06:58.991117 | localhost | Region: us-east-2
2025-09-16 00:06:58.991134 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-16 00:06:58.991151 | localhost | Product Name: t3.small
2025-09-16 00:06:58.991167 | localhost | Interface IP: 3.14.146.131
2025-09-16 00:06:59.007237 | 
2025-09-16 00:06:59.007335 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-16 00:06:59.493781 | localhost -> localhost | changed
2025-09-16 00:06:59.499450 | 
2025-09-16 00:06:59.499520 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-16 00:07:00.356870 | localhost -> localhost | changed
2025-09-16 00:07:00.395915 | 
2025-09-16 00:07:00.396000 | PLAY [all:!appliance*]
2025-09-16 00:07:00.420546 | 
2025-09-16 00:07:00.420636 | TASK [include_role : start-zuul-console]
2025-09-16 00:07:00.440942 | controller | ok
2025-09-16 00:07:00.454710 | 
2025-09-16 00:07:00.455071 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-16 00:07:01.153217 | controller | ok
2025-09-16 00:07:01.165534 | 
2025-09-16 00:07:01.165641 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-16 00:07:03.260618 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-16 00:07:03.267134 | 
2025-09-16 00:07:03.267208 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-16 00:07:03.393676 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.399795 | 
2025-09-16 00:07:03.399867 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-16 00:07:03.434075 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.440068 | 
2025-09-16 00:07:03.440149 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-16 00:07:03.464389 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.470773 | 
2025-09-16 00:07:03.470847 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-16 00:07:03.495313 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.501898 | 
2025-09-16 00:07:03.501974 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-16 00:07:03.526187 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.532043 | 
2025-09-16 00:07:03.532208 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-16 00:07:03.556337 | controller | skipping: Conditional result was False
2025-09-16 00:07:03.573207 | 
2025-09-16 00:07:03.573330 | TASK [Disable Fedora Modular]
2025-09-16 00:07:04.345848 | controller | changed
2025-09-16 00:07:04.354966 | 
2025-09-16 00:07:04.355108 | TASK [Enable EPEL]
2025-09-16 00:07:04.381216 | controller | skipping: Conditional result was False
2025-09-16 00:07:04.390542 | 
2025-09-16 00:07:04.390697 | TASK [Register the RHEL node]
2025-09-16 00:07:04.533221 | 
2025-09-16 00:07:04.533378 | TASK [Show the subscription-manager status]
2025-09-16 00:07:04.688999 | controller | skipping: Conditional result was False
2025-09-16 00:07:04.695570 | 
2025-09-16 00:07:04.695641 | TASK [Enable EPEL on RHEL]
2025-09-16 00:07:04.819769 | controller | skipping: Conditional result was False
2025-09-16 00:07:04.826449 | 
2025-09-16 00:07:04.826533 | TASK [Install git and tox]
2025-09-16 00:08:28.274536 | controller | changed
2025-09-16 00:08:28.289266 | 
2025-09-16 00:08:28.289441 | TASK [include_role : prepare-workspace]
2025-09-16 00:08:28.319805 | controller | ok
2025-09-16 00:08:28.347538 | 
2025-09-16 00:08:28.347750 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-16 00:08:28.843796 | controller | ok
2025-09-16 00:08:28.859585 | 
2025-09-16 00:08:28.859703 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-16 00:08:47.413191 | controller | Output suppressed because no_log was given
2025-09-16 00:08:47.430176 | 
2025-09-16 00:08:47.430305 | TASK [include_role : prepare-workspace-openshift]
2025-09-16 00:08:47.456137 | controller | skipping: Conditional result was False
2025-09-16 00:08:47.479394 | 
2025-09-16 00:08:47.479499 | PLAY [all:!appliance]
2025-09-16 00:08:47.560890 | 
2025-09-16 00:08:47.561014 | TASK [Run add-build-sshkey role (RSA)]
2025-09-16 00:08:47.592305 | controller | ok
2025-09-16 00:08:47.607253 | 
2025-09-16 00:08:47.607366 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-16 00:08:47.898162 | controller -> localhost | ok
2025-09-16 00:08:47.907751 | 
2025-09-16 00:08:47.907833 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-16 00:08:47.940361 | controller | ok
2025-09-16 00:08:47.955386 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-16 00:08:47.961312 | 
2025-09-16 00:08:47.961373 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-16 00:08:48.546575 | controller -> localhost | Generating public/private rsa key pair.
2025-09-16 00:08:48.546854 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_rsa.
2025-09-16 00:08:48.546885 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_rsa.pub.
2025-09-16 00:08:48.546906 | controller -> localhost | The key fingerprint is:
2025-09-16 00:08:48.546926 | controller -> localhost | SHA256:GlJ6EES8GTnzZ6gbtWavSZvW/ZgcNwRUQTFvFxwNYhg zuul-build-sshkey
2025-09-16 00:08:48.546944 | controller -> localhost | The key's randomart image is:
2025-09-16 00:08:48.546963 | controller -> localhost | +---[RSA 2048]----+
2025-09-16 00:08:48.546980 | controller -> localhost | |   ++.    E=Ooo+o|
2025-09-16 00:08:48.546999 | controller -> localhost | |    *.   ... + .o|
2025-09-16 00:08:48.547018 | controller -> localhost | |    .B..  .   o .|
2025-09-16 00:08:48.547042 | controller -> localhost | |    o++ o  . . . |
2025-09-16 00:08:48.547062 | controller -> localhost | |    ooo+S   .    |
2025-09-16 00:08:48.547093 | controller -> localhost | |    oo+o   .     |
2025-09-16 00:08:48.547119 | controller -> localhost | |     =oo .. o    |
2025-09-16 00:08:48.547138 | controller -> localhost | |    ...+o..= .   |
2025-09-16 00:08:48.547155 | controller -> localhost | |     .=.  +..    |
2025-09-16 00:08:48.547175 | controller -> localhost | +----[SHA256]-----+
2025-09-16 00:08:48.547231 | controller -> localhost | ok: Runtime: 0:00:00.133326
2025-09-16 00:08:48.554388 | 
2025-09-16 00:08:48.554475 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-16 00:08:48.586481 | controller | ok
2025-09-16 00:08:48.598457 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-16 00:08:48.612059 | 
2025-09-16 00:08:48.612203 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-16 00:08:48.637611 | controller | skipping: Conditional result was False
2025-09-16 00:08:48.646405 | 
2025-09-16 00:08:48.646558 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-16 00:08:49.392394 | controller | changed
2025-09-16 00:08:49.417096 | 
2025-09-16 00:08:49.417331 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-16 00:08:49.794684 | controller | ok
2025-09-16 00:08:49.811434 | 
2025-09-16 00:08:49.811539 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-16 00:08:51.130888 | controller | changed
2025-09-16 00:08:51.140945 | 
2025-09-16 00:08:51.141111 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-16 00:08:52.487041 | controller | changed
2025-09-16 00:08:52.495408 | 
2025-09-16 00:08:52.495531 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-16 00:08:52.522147 | controller | skipping: Conditional result was False
2025-09-16 00:08:52.541849 | 
2025-09-16 00:08:52.542070 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-16 00:08:53.013453 | controller -> localhost | changed
2025-09-16 00:08:53.028660 | 
2025-09-16 00:08:53.028873 | TASK [add-build-sshkey : Add back temp key]
2025-09-16 00:08:53.341757 | controller -> localhost | Identity added: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_rsa (zuul-build-sshkey)
2025-09-16 00:08:53.342053 | controller -> localhost | ok: Runtime: 0:00:00.009385
2025-09-16 00:08:53.349342 | 
2025-09-16 00:08:53.349408 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-16 00:08:53.865308 | controller | ok
2025-09-16 00:08:53.873152 | 
2025-09-16 00:08:53.873257 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-16 00:08:53.910563 | controller | skipping: Conditional result was False
2025-09-16 00:08:53.930218 | 
2025-09-16 00:08:53.930388 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-16 00:08:53.966534 | controller | ok
2025-09-16 00:08:53.989820 | 
2025-09-16 00:08:53.989920 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-16 00:08:54.275873 | controller -> localhost | ok
2025-09-16 00:08:54.283268 | 
2025-09-16 00:08:54.283353 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-16 00:08:54.315212 | controller | ok
2025-09-16 00:08:54.327216 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-16 00:08:54.334100 | 
2025-09-16 00:08:54.334174 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-16 00:08:54.644356 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-16 00:08:54.644674 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_ecdsa.
2025-09-16 00:08:54.644706 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_ecdsa.pub.
2025-09-16 00:08:54.644756 | controller -> localhost | The key fingerprint is:
2025-09-16 00:08:54.644780 | controller -> localhost | SHA256:fkOj98xCEP8eD7anDshjs9dImA3xLgTeFUw66/NqOMY zuul-build-sshkey
2025-09-16 00:08:54.644799 | controller -> localhost | The key's randomart image is:
2025-09-16 00:08:54.644818 | controller -> localhost | +---[ECDSA 521]---+
2025-09-16 00:08:54.644835 | controller -> localhost | |         oo.     |
2025-09-16 00:08:54.644853 | controller -> localhost | |      . o.o      |
2025-09-16 00:08:54.644870 | controller -> localhost | |     . oo*       |
2025-09-16 00:08:54.644887 | controller -> localhost | |      . =oo      |
2025-09-16 00:08:54.644904 | controller -> localhost | |       .SBo.     |
2025-09-16 00:08:54.644920 | controller -> localhost | |       +++=.=    |
2025-09-16 00:08:54.644937 | controller -> localhost | |     . .@+== =   |
2025-09-16 00:08:54.644954 | controller -> localhost | |      E..O+*+ o  |
2025-09-16 00:08:54.644970 | controller -> localhost | |     . ooo.o*o   |
2025-09-16 00:08:54.644987 | controller -> localhost | +----[SHA256]-----+
2025-09-16 00:08:54.645040 | controller -> localhost | ok: Runtime: 0:00:00.012884
2025-09-16 00:08:54.653036 | 
2025-09-16 00:08:54.653110 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-16 00:08:54.686564 | controller | ok
2025-09-16 00:08:54.695403 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-16 00:08:54.705461 | 
2025-09-16 00:08:54.705557 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-16 00:08:54.741887 | controller | skipping: Conditional result was False
2025-09-16 00:08:54.753414 | 
2025-09-16 00:08:54.753599 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-16 00:08:55.257998 | controller | changed
2025-09-16 00:08:55.273125 | 
2025-09-16 00:08:55.273291 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-16 00:08:55.615418 | controller | ok
2025-09-16 00:08:55.626433 | 
2025-09-16 00:08:55.626625 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-16 00:08:56.890648 | controller | changed
2025-09-16 00:08:56.898410 | 
2025-09-16 00:08:56.898488 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-16 00:08:58.154452 | controller | changed
2025-09-16 00:08:58.168957 | 
2025-09-16 00:08:58.169162 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-16 00:08:58.212189 | controller | skipping: Conditional result was False
2025-09-16 00:08:58.226482 | 
2025-09-16 00:08:58.226710 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-16 00:08:58.513335 | controller -> localhost | changed
2025-09-16 00:08:58.531226 | 
2025-09-16 00:08:58.531404 | TASK [add-build-sshkey : Add back temp key]
2025-09-16 00:08:58.849789 | controller -> localhost | Identity added: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/4064fa99145e452fbd9f8a35ef0a40a0_id_ecdsa (zuul-build-sshkey)
2025-09-16 00:08:58.850031 | controller -> localhost | ok: Runtime: 0:00:00.015264
2025-09-16 00:08:58.856759 | 
2025-09-16 00:08:58.856829 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-16 00:08:59.187946 | controller | ok
2025-09-16 00:08:59.193588 | 
2025-09-16 00:08:59.193662 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-16 00:08:59.231198 | controller | skipping: Conditional result was False
2025-09-16 00:08:59.299109 | 
2025-09-16 00:08:59.299234 | TASK [include_role : remove-zuul-sshkey]
2025-09-16 00:08:59.323750 | controller | skipping: Conditional result was False
2025-09-16 00:08:59.330716 | 
2025-09-16 00:08:59.330826 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-16 00:08:59.644710 | controller | ok: "logs"
2025-09-16 00:08:59.645317 | controller | ok: All items complete
2025-09-16 00:08:59.645358 | 
2025-09-16 00:08:59.911920 | controller | ok: "artifacts"
2025-09-16 00:09:00.306804 | controller | ok: "docs"
2025-09-16 00:09:00.317192 | 
2025-09-16 00:09:00.317329 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-16 00:09:00.646219 | controller | changed: "logs"
2025-09-16 00:09:00.938516 | controller | changed: "artifacts"
2025-09-16 00:09:01.234598 | controller | changed: "docs"
2025-09-16 00:09:01.300092 | 
2025-09-16 00:09:01.300273 | PLAY RECAP
2025-09-16 00:09:01.300336 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-16 00:09:01.300371 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-16 00:09:01.300400 | 
2025-09-16 00:09:01.507836 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-16 00:09:01.508774 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-16 00:09:02.158040 | 
2025-09-16 00:09:02.158373 | PLAY [all]
2025-09-16 00:09:02.184829 | 
2025-09-16 00:09:02.185000 | TASK [Install binary dependencies]
2025-09-16 00:09:02.247158 | controller | ok
2025-09-16 00:09:02.273616 | 
2025-09-16 00:09:02.273778 | TASK [bindep : Include find tasks]
2025-09-16 00:09:02.313768 | controller | ok
2025-09-16 00:09:02.322851 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-16 00:09:02.329853 | 
2025-09-16 00:09:02.330002 | TASK [bindep : Look for bindep.txt]
2025-09-16 00:09:03.043929 | controller | ok
2025-09-16 00:09:03.055229 | 
2025-09-16 00:09:03.055362 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:09:03.105896 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.113344 | 
2025-09-16 00:09:03.113448 | TASK [bindep : Look for other-requirements.txt]
2025-09-16 00:09:03.479545 | controller | ok
2025-09-16 00:09:03.485588 | 
2025-09-16 00:09:03.485670 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:09:03.509661 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.516343 | 
2025-09-16 00:09:03.516436 | TASK [bindep : Look for bindep fallback file]
2025-09-16 00:09:03.551037 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.568374 | 
2025-09-16 00:09:03.568586 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:09:03.597420 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.610949 | 
2025-09-16 00:09:03.611089 | TASK [bindep : Include bindep tasks]
2025-09-16 00:09:03.657007 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.667284 | 
2025-09-16 00:09:03.667386 | TASK [bindep : Include install tasks]
2025-09-16 00:09:03.705636 | controller | skipping: Conditional result was False
2025-09-16 00:09:03.715881 | 
2025-09-16 00:09:03.716015 | LOOP [bindep : Include package tasks]
2025-09-16 00:09:03.810427 | 
2025-09-16 00:09:03.810609 | TASK [Run test-setup role]
2025-09-16 00:09:03.835409 | controller | ok
2025-09-16 00:09:03.879377 | 
2025-09-16 00:09:03.879525 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-16 00:09:04.214842 | controller | ok
2025-09-16 00:09:04.221605 | 
2025-09-16 00:09:04.221687 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-16 00:09:04.378494 | controller | skipping: Conditional result was False
2025-09-16 00:09:04.419073 | 
2025-09-16 00:09:04.419177 | PLAY RECAP
2025-09-16 00:09:04.419217 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-16 00:09:04.419237 | 
2025-09-16 00:09:04.527408 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-16 00:09:04.528432 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-16 00:09:05.186505 | 
2025-09-16 00:09:05.186693 | PLAY [controller]
2025-09-16 00:09:05.208655 | 
2025-09-16 00:09:05.208814 | TASK [Create the /root directory]
2025-09-16 00:09:05.958131 | controller | ok
2025-09-16 00:09:05.965938 | 
2025-09-16 00:09:05.966169 | TASK [Install glibc-langpack-en]
2025-09-16 00:09:14.088551 | controller | ok: Nothing to do
2025-09-16 00:09:14.094671 | 
2025-09-16 00:09:14.094862 | TASK [Ensure controller directory exists]
2025-09-16 00:09:14.540209 | controller | changed
2025-09-16 00:09:14.561582 | 
2025-09-16 00:09:14.561708 | TASK [Install container runtime]
2025-09-16 00:09:14.613672 | controller | ok
2025-09-16 00:09:14.650824 | 
2025-09-16 00:09:14.650946 | LOOP [ensure-podman : Find distribution installation]
2025-09-16 00:09:14.688454 | controller | ok: "/var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-16 00:09:14.703525 | controller | included: /var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-16 00:09:14.710172 | 
2025-09-16 00:09:14.710254 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-16 00:10:28.293988 | controller | changed
2025-09-16 00:10:28.300614 | 
2025-09-16 00:10:28.300685 | TASK [ensure-podman : Fetch podman version]
2025-09-16 00:10:29.045639 | controller | Client:       Podman Engine
2025-09-16 00:10:29.045721 | controller | Version:      4.6.2
2025-09-16 00:10:29.045757 | controller | API Version:  4.6.2
2025-09-16 00:10:29.045784 | controller | Go Version:   go1.19.12
2025-09-16 00:10:29.045821 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-16 00:10:29.045849 | controller | OS/Arch:      linux/amd64
2025-09-16 00:10:29.428313 | controller | ok: Runtime: 0:00:00.218842
2025-09-16 00:10:29.434433 | 
2025-09-16 00:10:29.434506 | TASK [ensure-podman : Print podman version installed]
2025-09-16 00:10:29.474490 | Podman version: Client:       Podman Engine
2025-09-16 00:10:29.474632 | Version:      4.6.2
2025-09-16 00:10:29.474685 | API Version:  4.6.2
2025-09-16 00:10:29.474708 | Go Version:   go1.19.12
2025-09-16 00:10:29.474742 | Built:        Mon Aug 28 19:38:31 2023
2025-09-16 00:10:29.474768 | OS/Arch:      linux/amd64
2025-09-16 00:10:29.485919 | 
2025-09-16 00:10:29.486170 | TASK [ensure-podman : Validate podman engine]
2025-09-16 00:10:29.623005 | controller | skipping: Conditional result was False
2025-09-16 00:10:29.635517 | 
2025-09-16 00:10:29.635800 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-16 00:10:29.672209 | controller | skipping: Conditional result was False
2025-09-16 00:10:29.700549 | 
2025-09-16 00:10:29.701055 | TASK [Ensure python3.8 is present]
2025-09-16 00:10:29.737675 | controller | skipping: Conditional result was False
2025-09-16 00:10:29.746875 | 
2025-09-16 00:10:29.746988 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-16 00:10:29.779973 | controller | ok
2025-09-16 00:10:29.802814 | 
2025-09-16 00:10:29.802924 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-16 00:10:33.639230 | controller | ok: Nothing to do
2025-09-16 00:10:33.652406 | 
2025-09-16 00:10:33.652559 | TASK [our-ensure-python : Also install python3-devel]
2025-09-16 00:10:47.037464 | controller | changed
2025-09-16 00:10:47.048483 | 
2025-09-16 00:10:47.048555 | TASK [Run ensure-virtualenv role]
2025-09-16 00:10:47.068432 | controller | ok
2025-09-16 00:10:47.092140 | 
2025-09-16 00:10:47.092293 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-16 00:10:47.482363 | controller | /usr/bin/virtualenv
2025-09-16 00:10:47.745016 | controller | ok: Runtime: 0:00:00.004229
2025-09-16 00:10:47.754716 | 
2025-09-16 00:10:47.754845 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-16 00:10:47.789653 | controller | skipping: Conditional result was False
2025-09-16 00:10:47.789953 | controller | ok: All items complete
2025-09-16 00:10:47.789980 | 
2025-09-16 00:10:47.802932 | 
2025-09-16 00:10:47.803072 | TASK [Find the full path of the Python interpreter]
2025-09-16 00:10:48.225439 | controller | /usr/bin/python3
2025-09-16 00:10:48.430777 | controller | ok
2025-09-16 00:10:48.443950 | 
2025-09-16 00:10:48.444103 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-16 00:10:49.947936 | controller | created virtual environment CPython3.11.0.final.0-64 in 743ms
2025-09-16 00:10:49.994372 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-16 00:10:49.994437 | 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-16 00:10:49.994456 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-16 00:10:49.994480 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-16 00:10:50.100414 | controller | changed
2025-09-16 00:10:50.114898 | 
2025-09-16 00:10:50.115088 | TASK [Set selinux package]
2025-09-16 00:10:50.144295 | controller | ok
2025-09-16 00:10:50.153466 | 
2025-09-16 00:10:50.153633 | TASK [Set selinux package (Fedora)]
2025-09-16 00:10:50.197477 | controller | ok
2025-09-16 00:10:50.203315 | 
2025-09-16 00:10:50.203389 | TASK [Install selinux into virtualenv]
2025-09-16 00:10:52.778339 | controller | Collecting selinux-please-lie-to-me
2025-09-16 00:10:52.871050 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-16 00:10:53.400243 | controller | Collecting setuptools<50.0.0
2025-09-16 00:10:53.415743 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-16 00:10:53.559088 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 5.9 MB/s eta 0:00:00
2025-09-16 00:10:53.730399 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-16 00:10:53.730838 | controller |   Attempting uninstall: setuptools
2025-09-16 00:10:53.735685 | controller |     Found existing installation: setuptools 62.6.0
2025-09-16 00:10:53.847333 | controller |     Uninstalling setuptools-62.6.0:
2025-09-16 00:10:53.862644 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-16 00:10:54.580582 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-16 00:10:54.786021 | controller |
2025-09-16 00:10:55.000666 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-16 00:10:55.000720 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-16 00:10:55.365635 | controller | ok: Runtime: 0:00:04.339303
2025-09-16 00:10:55.377948 | 
2025-09-16 00:10:55.378083 | TASK [Install pytest-forked into virtualenv]
2025-09-16 00:10:56.579549 | controller | Collecting pytest-forked
2025-09-16 00:10:56.671068 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-16 00:10:56.729025 | controller | Collecting py
2025-09-16 00:10:56.743896 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-16 00:10:56.782050 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-09-16 00:10:56.958078 | controller | Collecting pytest>=3.10
2025-09-16 00:10:56.972679 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-16 00:10:57.034729 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00
2025-09-16 00:10:57.087192 | controller | Collecting iniconfig>=1
2025-09-16 00:10:57.101836 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-16 00:10:57.168481 | controller | Collecting packaging>=20
2025-09-16 00:10:57.182703 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-16 00:10:57.195348 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.1 MB/s eta 0:00:00
2025-09-16 00:10:57.241094 | controller | Collecting pluggy<2,>=1.5
2025-09-16 00:10:57.255345 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-16 00:10:57.330034 | controller | Collecting pygments>=2.7.2
2025-09-16 00:10:57.344457 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-16 00:10:57.518276 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 7.1 MB/s eta 0:00:00
2025-09-16 00:10:57.650186 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-16 00:10:59.951935 | 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-16 00:10:59.968042 | controller |
2025-09-16 00:11:00.169276 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-16 00:11:00.169322 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-16 00:11:00.550603 | controller | ok: Runtime: 0:00:04.316410
2025-09-16 00:11:00.563317 | 
2025-09-16 00:11:00.563460 | TASK [Update pip]
2025-09-16 00:11:01.706838 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-16 00:11:01.983277 | controller | Collecting pip
2025-09-16 00:11:02.072574 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-16 00:11:02.236622 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.1 MB/s eta 0:00:00
2025-09-16 00:11:02.407139 | controller | Installing collected packages: pip
2025-09-16 00:11:02.407942 | controller |   Attempting uninstall: pip
2025-09-16 00:11:02.413529 | controller |     Found existing installation: pip 22.2.2
2025-09-16 00:11:02.674925 | controller |     Uninstalling pip-22.2.2:
2025-09-16 00:11:02.705123 | controller |       Successfully uninstalled pip-22.2.2
2025-09-16 00:11:04.428769 | controller | Successfully installed pip-25.2
2025-09-16 00:11:04.718264 | controller | ok: Runtime: 0:00:03.514563
2025-09-16 00:11:04.732019 | 
2025-09-16 00:11:04.732201 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-16 00:11:05.254479 | controller | changed
2025-09-16 00:11:05.266456 | 
2025-09-16 00:11:05.266624 | TASK [Install ansible into virtualenv]
2025-09-16 00:11:06.410528 | controller | Processing ./src/github.com/ansible/ansible
2025-09-16 00:11:06.417080 | controller |   Installing build dependencies: started
2025-09-16 00:11:08.270150 | controller |   Installing build dependencies: finished with status 'done'
2025-09-16 00:11:08.271271 | controller |   Getting requirements to build wheel: started
2025-09-16 00:11:09.808573 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-16 00:11:10.723465 | controller |   Preparing metadata (pyproject.toml): started
2025-09-16 00:11:10.723515 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-16 00:11:10.728205 | 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-16 00:11:10.733020 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-16 00:11:10.970793 | controller | ERROR
2025-09-16 00:11:10.970982 | controller | {
2025-09-16 00:11:10.971010 | controller |   "delta": "0:00:05.122826",
2025-09-16 00:11:10.971032 | controller |   "end": "2025-09-16 00:11:10.878035",
2025-09-16 00:11:10.971049 | controller |   "msg": "non-zero return code",
2025-09-16 00:11:10.971078 | controller |   "rc": 1,
2025-09-16 00:11:10.971095 | controller |   "start": "2025-09-16 00:11:05.755209"
2025-09-16 00:11:10.971110 | controller | }
failure
2025-09-16 00:11:10.972949 | 
2025-09-16 00:11:10.972995 | PLAY RECAP
2025-09-16 00:11:10.973036 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-16 00:11:10.973055 | 
2025-09-16 00:11:11.086442 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-16 00:11:11.087418 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-16 00:11:11.703850 | 
2025-09-16 00:11:11.703972 | PLAY [all]
2025-09-16 00:11:11.725252 | 
2025-09-16 00:11:11.725371 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-16 00:11:12.506855 | controller | changed: non-zero return code
2025-09-16 00:11:12.512903 | 
2025-09-16 00:11:12.513000 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-16 00:11:12.538952 | controller | skipping: Conditional result was False
2025-09-16 00:11:12.554838 | 
2025-09-16 00:11:12.555003 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-16 00:11:12.594210 | 
2025-09-16 00:11:12.594452 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-16 00:11:12.630442 | 
2025-09-16 00:11:12.630685 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-16 00:11:12.657540 | controller | skipping: Conditional result was False
2025-09-16 00:11:12.666576 | 
2025-09-16 00:11:12.666682 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-16 00:11:12.703022 | 
2025-09-16 00:11:12.703230 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-16 00:11:12.730316 | controller | skipping: Conditional result was False
2025-09-16 00:11:12.739711 | 
2025-09-16 00:11:12.739854 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-16 00:11:12.766567 | controller | skipping: Conditional result was False
2025-09-16 00:11:12.776187 | 
2025-09-16 00:11:12.776295 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-16 00:11:12.806518 | controller | skipping: Conditional result was False
2025-09-16 00:11:12.850180 | 
2025-09-16 00:11:12.850297 | PLAY RECAP
2025-09-16 00:11:12.850344 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-16 00:11:12.850366 | 
2025-09-16 00:11:12.965006 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-16 00:11:12.966728 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-16 00:11:13.644866 | 
2025-09-16 00:11:13.645068 | PLAY [all:!appliance*]
2025-09-16 00:11:13.667142 | 
2025-09-16 00:11:13.667252 | TASK [unregister the node]
2025-09-16 00:11:13.797077 | controller | skipping: Conditional result was False
2025-09-16 00:11:13.803554 | 
2025-09-16 00:11:13.803646 | TASK [include_role : fetch-output]
2025-09-16 00:11:13.854171 | controller | ok
2025-09-16 00:11:13.874048 | 
2025-09-16 00:11:13.874166 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-16 00:11:13.939714 | controller | skipping: Conditional result was False
2025-09-16 00:11:13.946641 | 
2025-09-16 00:11:13.946747 | TASK [fetch-output : Set log path for single node]
2025-09-16 00:11:13.987604 | controller | ok
2025-09-16 00:11:13.993135 | 
2025-09-16 00:11:13.993203 | LOOP [fetch-output : Ensure local output dirs]
2025-09-16 00:11:14.497563 | controller -> localhost | ok: "/var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/logs"
2025-09-16 00:11:14.759935 | controller -> localhost | changed: "/var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/artifacts"
2025-09-16 00:11:15.009295 | controller -> localhost | changed: "/var/lib/zuul/builds/4064fa99145e452fbd9f8a35ef0a40a0/work/docs"
2025-09-16 00:11:15.031551 | 
2025-09-16 00:11:15.031718 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-16 00:11:16.262076 | controller | changed:
2025-09-16 00:11:16.262408 | controller | .d..t...... ./
2025-09-16 00:11:16.262470 | controller | cd+++++++++ controller/
2025-09-16 00:11:16.262543 | controller | changed: All items complete
2025-09-16 00:11:16.262588 | 
2025-09-16 00:11:17.366262 | controller | changed: .d..t...... ./
2025-09-16 00:11:18.388502 | controller | changed: .d..t...... ./
2025-09-16 00:11:18.423451 | 
2025-09-16 00:11:18.423652 | TASK [include_role : fetch-output-openshift]
2025-09-16 00:11:18.452221 | controller | skipping: Conditional result was False
2025-09-16 00:11:18.466844 | 
2025-09-16 00:11:18.467176 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-16 00:11:18.519392 | controller | skipping: Conditional result was False
2025-09-16 00:11:18.531591 | controller | skipping: Conditional result was False
2025-09-16 00:11:18.587515 | 
2025-09-16 00:11:18.587650 | PLAY [localhost]
2025-09-16 00:11:18.606875 | 
2025-09-16 00:11:18.607004 | TASK [Run Zuul manifest role]
2025-09-16 00:11:18.628614 | localhost | ok
2025-09-16 00:11:18.650272 | 
2025-09-16 00:11:18.650454 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-16 00:11:19.128666 | localhost | changed
2025-09-16 00:11:19.133351 | 
2025-09-16 00:11:19.133420 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-16 00:11:19.161537 | localhost | ok
2025-09-16 00:11:19.169850 | 
2025-09-16 00:11:19.169925 | TASK [Set zuul-log-path fact]
2025-09-16 00:11:19.188189 | localhost | ok
2025-09-16 00:11:19.201931 | 
2025-09-16 00:11:19.202037 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-16 00:11:19.233375 | localhost | ok
2025-09-16 00:11:19.247633 | 
2025-09-16 00:11:19.247784 | LOOP [Run upload-logs-swift role]
2025-09-16 00:11:19.283532 | localhost | Output suppressed because no_log was given
2025-09-16 00:11:19.321513 | 
2025-09-16 00:11:19.321663 | TASK [Set zuul-log-path fact]
2025-09-16 00:11:19.347484 | localhost | skipping: Conditional result was False
2025-09-16 00:11:19.352654 | 
2025-09-16 00:11:19.352747 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-16 00:11:19.797685 | localhost -> localhost | ok: Runtime: 0:00:00.008654
2025-09-16 00:11:19.810953 | 
2025-09-16 00:11:19.811125 | TASK [upload-logs-swift : Upload logs to swift]