2025-09-24 00:11:50.206524 | Job console starting...
2025-09-24 00:11:50.218603 | Updating repositories
2025-09-24 00:11:50.828133 | Preparing job workspace
2025-09-24 00:11:54.347112 | Running Ansible setup...
2025-09-24 00:12:00.383800 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-24 00:12:00.989929 | 
2025-09-24 00:12:00.990061 | PLAY [localhost]
2025-09-24 00:12:00.998751 | 
2025-09-24 00:12:00.998822 | TASK [Gathering Facts]
2025-09-24 00:12:02.138119 | localhost | ok
2025-09-24 00:12:02.167347 | 
2025-09-24 00:12:02.167461 | TASK [Setup log path fact]
2025-09-24 00:12:02.201170 | localhost | ok
2025-09-24 00:12:02.222081 | 
2025-09-24 00:12:02.222195 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-24 00:12:02.265375 | localhost | ok
2025-09-24 00:12:02.277563 | 
2025-09-24 00:12:02.277655 | TASK [emit-job-header : Print job information]
2025-09-24 00:12:02.329235 | # Job Information
2025-09-24 00:12:02.329447 | Ansible Version: 2.15.12
2025-09-24 00:12:02.329493 | Job: ansible-test-sanity-docker-devel
2025-09-24 00:12:02.329524 | Pipeline: periodic
2025-09-24 00:12:02.329551 | Executor: ze02.softwarefactory-project.io
2025-09-24 00:12:02.329576 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-24 00:12:02.329607 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/690/ansible/690aec6a84404bee9417f00eb4a78bf5/
2025-09-24 00:12:02.329634 | Event ID: 3b09a8e0ff9c49ffb90e8d2a452c8a0a
2025-09-24 00:12:02.336090 | 
2025-09-24 00:12:02.336197 | LOOP [emit-job-header : Print node information]
2025-09-24 00:12:02.448918 | localhost | ok:
2025-09-24 00:12:02.449169 | localhost | # Node Information
2025-09-24 00:12:02.449196 | localhost | Inventory Hostname: controller
2025-09-24 00:12:02.449215 | localhost | Hostname: ip-172-16-104-35
2025-09-24 00:12:02.449234 | localhost | Username: zuul-worker
2025-09-24 00:12:02.449256 | localhost | Distro: Fedora 37
2025-09-24 00:12:02.449274 | localhost | Provider: ansible-us-east-2
2025-09-24 00:12:02.449291 | localhost | Region: us-east-2
2025-09-24 00:12:02.449308 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-24 00:12:02.449324 | localhost | Product Name: t3.small
2025-09-24 00:12:02.449341 | localhost | Interface IP: 3.145.185.22
2025-09-24 00:12:02.465102 | 
2025-09-24 00:12:02.465235 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-24 00:12:02.970502 | localhost -> localhost | changed
2025-09-24 00:12:02.976250 | 
2025-09-24 00:12:02.976320 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-24 00:12:04.025015 | localhost -> localhost | changed
2025-09-24 00:12:04.073083 | 
2025-09-24 00:12:04.073214 | PLAY [all:!appliance*]
2025-09-24 00:12:04.097889 | 
2025-09-24 00:12:04.098053 | TASK [include_role : start-zuul-console]
2025-09-24 00:12:04.128651 | controller | ok
2025-09-24 00:12:04.142838 | 
2025-09-24 00:12:04.142940 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-24 00:12:04.843448 | controller | ok
2025-09-24 00:12:04.884526 | 
2025-09-24 00:12:04.885159 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-24 00:12:06.482747 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-24 00:12:06.496518 | 
2025-09-24 00:12:06.496660 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-24 00:12:06.655466 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.672244 | 
2025-09-24 00:12:06.672458 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-24 00:12:06.702698 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.719835 | 
2025-09-24 00:12:06.720036 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-24 00:12:06.758377 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.769854 | 
2025-09-24 00:12:06.769983 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-24 00:12:06.807287 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.823228 | 
2025-09-24 00:12:06.823378 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-24 00:12:06.854224 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.868839 | 
2025-09-24 00:12:06.868988 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-24 00:12:06.906682 | controller | skipping: Conditional result was False
2025-09-24 00:12:06.922524 | 
2025-09-24 00:12:06.922614 | TASK [Disable Fedora Modular]
2025-09-24 00:12:07.651156 | controller | changed
2025-09-24 00:12:07.664850 | 
2025-09-24 00:12:07.664988 | TASK [Enable EPEL]
2025-09-24 00:12:07.693506 | controller | skipping: Conditional result was False
2025-09-24 00:12:07.709470 | 
2025-09-24 00:12:07.709649 | TASK [Register the RHEL node]
2025-09-24 00:12:07.875595 | 
2025-09-24 00:12:07.875915 | TASK [Show the subscription-manager status]
2025-09-24 00:12:08.065400 | controller | skipping: Conditional result was False
2025-09-24 00:12:08.071910 | 
2025-09-24 00:12:08.071975 | TASK [Enable EPEL on RHEL]
2025-09-24 00:12:08.209660 | controller | skipping: Conditional result was False
2025-09-24 00:12:08.215963 | 
2025-09-24 00:12:08.216029 | TASK [Install git and tox]
2025-09-24 00:13:47.145201 | controller | changed
2025-09-24 00:13:47.158462 | 
2025-09-24 00:13:47.158589 | TASK [include_role : prepare-workspace]
2025-09-24 00:13:47.197494 | controller | ok
2025-09-24 00:13:47.232730 | 
2025-09-24 00:13:47.232836 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-24 00:13:47.842018 | controller | ok
2025-09-24 00:13:47.855542 | 
2025-09-24 00:13:47.855726 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-24 00:14:00.563281 | controller | Output suppressed because no_log was given
2025-09-24 00:14:00.632730 | 
2025-09-24 00:14:00.632922 | TASK [include_role : prepare-workspace-openshift]
2025-09-24 00:14:00.675734 | controller | skipping: Conditional result was False
2025-09-24 00:14:00.699441 | 
2025-09-24 00:14:00.699598 | PLAY [all:!appliance]
2025-09-24 00:14:00.717147 | 
2025-09-24 00:14:00.717282 | TASK [Run add-build-sshkey role (RSA)]
2025-09-24 00:14:00.760068 | controller | ok
2025-09-24 00:14:00.775838 | 
2025-09-24 00:14:00.775947 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-24 00:14:01.057530 | controller -> localhost | ok
2025-09-24 00:14:01.073286 | 
2025-09-24 00:14:01.073496 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-24 00:14:01.116125 | controller | ok
2025-09-24 00:14:01.146888 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-24 00:14:01.155120 | 
2025-09-24 00:14:01.155205 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-24 00:14:01.885034 | controller -> localhost | Generating public/private rsa key pair.
2025-09-24 00:14:01.885419 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_rsa.
2025-09-24 00:14:01.885491 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_rsa.pub.
2025-09-24 00:14:01.885537 | controller -> localhost | The key fingerprint is:
2025-09-24 00:14:01.885613 | controller -> localhost | SHA256:pOR/M9rQEkilVcseJ2xo0ut7WN2sE4sVt+G4EsES58I zuul-build-sshkey
2025-09-24 00:14:01.886119 | controller -> localhost | The key's randomart image is:
2025-09-24 00:14:01.886237 | controller -> localhost | +---[RSA 2048]----+
2025-09-24 00:14:01.886293 | controller -> localhost | |        o..      |
2025-09-24 00:14:01.886342 | controller -> localhost | |       =.+..     |
2025-09-24 00:14:01.886384 | controller -> localhost | |      =.==B .    |
2025-09-24 00:14:01.886425 | controller -> localhost | |     + *E+++. o  |
2025-09-24 00:14:01.886463 | controller -> localhost | |      + So.o B o |
2025-09-24 00:14:01.887094 | controller -> localhost | |       o oo = =  |
2025-09-24 00:14:01.887163 | controller -> localhost | |        =o=+ =   |
2025-09-24 00:14:01.887232 | controller -> localhost | |        .B+o=    |
2025-09-24 00:14:01.887280 | controller -> localhost | |        o... .   |
2025-09-24 00:14:01.887326 | controller -> localhost | +----[SHA256]-----+
2025-09-24 00:14:01.887423 | controller -> localhost | ok: Runtime: 0:00:00.191863
2025-09-24 00:14:01.905697 | 
2025-09-24 00:14:01.905861 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-24 00:14:01.952024 | controller | ok
2025-09-24 00:14:01.972817 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-24 00:14:01.986555 | 
2025-09-24 00:14:01.986646 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-24 00:14:02.014483 | controller | skipping: Conditional result was False
2025-09-24 00:14:02.025218 | 
2025-09-24 00:14:02.025333 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-24 00:14:03.212130 | controller | changed
2025-09-24 00:14:03.226374 | 
2025-09-24 00:14:03.226519 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-24 00:14:03.894881 | controller | ok
2025-09-24 00:14:03.907511 | 
2025-09-24 00:14:03.907650 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-24 00:14:05.338573 | controller | changed
2025-09-24 00:14:05.351163 | 
2025-09-24 00:14:05.351317 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-24 00:14:06.618618 | controller | changed
2025-09-24 00:14:06.631335 | 
2025-09-24 00:14:06.631471 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-24 00:14:06.659706 | controller | skipping: Conditional result was False
2025-09-24 00:14:06.674311 | 
2025-09-24 00:14:06.674453 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-24 00:14:07.120923 | controller -> localhost | changed
2025-09-24 00:14:07.147611 | 
2025-09-24 00:14:07.147799 | TASK [add-build-sshkey : Add back temp key]
2025-09-24 00:14:07.482290 | controller -> localhost | Identity added: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_rsa (zuul-build-sshkey)
2025-09-24 00:14:07.482790 | controller -> localhost | ok: Runtime: 0:00:00.013737
2025-09-24 00:14:07.496885 | 
2025-09-24 00:14:07.497021 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-24 00:14:08.037141 | controller | ok
2025-09-24 00:14:08.049577 | 
2025-09-24 00:14:08.050098 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-24 00:14:08.089093 | controller | skipping: Conditional result was False
2025-09-24 00:14:08.114332 | 
2025-09-24 00:14:08.114505 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-24 00:14:08.158519 | controller | ok
2025-09-24 00:14:08.185308 | 
2025-09-24 00:14:08.185429 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-24 00:14:08.486529 | controller -> localhost | ok
2025-09-24 00:14:08.493835 | 
2025-09-24 00:14:08.493907 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-24 00:14:08.525143 | controller | ok
2025-09-24 00:14:08.536433 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-24 00:14:08.543211 | 
2025-09-24 00:14:08.543276 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-24 00:14:08.842392 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-24 00:14:08.842585 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_ecdsa.
2025-09-24 00:14:08.842613 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_ecdsa.pub.
2025-09-24 00:14:08.842643 | controller -> localhost | The key fingerprint is:
2025-09-24 00:14:08.842681 | controller -> localhost | SHA256:LvGXS0XXhYOnxXcv+38Vrvh9c5czIxyH2gNiZNVDUlc zuul-build-sshkey
2025-09-24 00:14:08.842705 | controller -> localhost | The key's randomart image is:
2025-09-24 00:14:08.842724 | controller -> localhost | +---[ECDSA 521]---+
2025-09-24 00:14:08.842742 | controller -> localhost | |           .+= oE|
2025-09-24 00:14:08.842759 | controller -> localhost | |           .ooB.+|
2025-09-24 00:14:08.842775 | controller -> localhost | |          . .+oo+|
2025-09-24 00:14:08.842792 | controller -> localhost | |         o ......|
2025-09-24 00:14:08.842808 | controller -> localhost | |      . S   . oo.|
2025-09-24 00:14:08.842825 | controller -> localhost | |       + o + o.o.|
2025-09-24 00:14:08.842841 | controller -> localhost | |      . + = * +.o|
2025-09-24 00:14:08.842857 | controller -> localhost | |       . o + *.**|
2025-09-24 00:14:08.842872 | controller -> localhost | |          . ..o.%|
2025-09-24 00:14:08.842888 | controller -> localhost | +----[SHA256]-----+
2025-09-24 00:14:08.842934 | controller -> localhost | ok: Runtime: 0:00:00.014684
2025-09-24 00:14:08.849692 | 
2025-09-24 00:14:08.849773 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-24 00:14:08.880484 | controller | ok
2025-09-24 00:14:08.887952 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-24 00:14:08.897081 | 
2025-09-24 00:14:08.897148 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-24 00:14:08.921936 | controller | skipping: Conditional result was False
2025-09-24 00:14:08.928580 | 
2025-09-24 00:14:08.928643 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-24 00:14:09.377066 | controller | changed
2025-09-24 00:14:09.392849 | 
2025-09-24 00:14:09.392940 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-24 00:14:09.733046 | controller | ok
2025-09-24 00:14:09.748839 | 
2025-09-24 00:14:09.749020 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-24 00:14:11.003813 | controller | changed
2025-09-24 00:14:11.010889 | 
2025-09-24 00:14:11.010975 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-24 00:14:12.255660 | controller | changed
2025-09-24 00:14:12.269079 | 
2025-09-24 00:14:12.269235 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-24 00:14:12.307537 | controller | skipping: Conditional result was False
2025-09-24 00:14:12.319753 | 
2025-09-24 00:14:12.319898 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-24 00:14:12.652040 | controller -> localhost | changed
2025-09-24 00:14:12.665740 | 
2025-09-24 00:14:12.665836 | TASK [add-build-sshkey : Add back temp key]
2025-09-24 00:14:12.988708 | controller -> localhost | Identity added: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/690aec6a84404bee9417f00eb4a78bf5_id_ecdsa (zuul-build-sshkey)
2025-09-24 00:14:12.989111 | controller -> localhost | ok: Runtime: 0:00:00.008821
2025-09-24 00:14:13.002971 | 
2025-09-24 00:14:13.003141 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-24 00:14:13.361489 | controller | ok
2025-09-24 00:14:13.373482 | 
2025-09-24 00:14:13.373620 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-24 00:14:13.400794 | controller | skipping: Conditional result was False
2025-09-24 00:14:13.416922 | 
2025-09-24 00:14:13.417057 | TASK [include_role : remove-zuul-sshkey]
2025-09-24 00:14:13.432008 | controller | skipping: Conditional result was False
2025-09-24 00:14:13.442097 | 
2025-09-24 00:14:13.442233 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-24 00:14:13.771537 | controller | ok: "logs"
2025-09-24 00:14:13.772453 | controller | ok: All items complete
2025-09-24 00:14:13.772505 | 
2025-09-24 00:14:14.077315 | controller | ok: "artifacts"
2025-09-24 00:14:14.380964 | controller | ok: "docs"
2025-09-24 00:14:14.399311 | 
2025-09-24 00:14:14.399452 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-24 00:14:14.708754 | controller | changed: "logs"
2025-09-24 00:14:14.994938 | controller | changed: "artifacts"
2025-09-24 00:14:15.283414 | controller | changed: "docs"
2025-09-24 00:14:15.320855 | 
2025-09-24 00:14:15.320976 | PLAY RECAP
2025-09-24 00:14:15.321024 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-24 00:14:15.321050 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-24 00:14:15.321067 | 
2025-09-24 00:14:15.489631 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-24 00:14:15.491752 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-24 00:14:16.087825 | 
2025-09-24 00:14:16.087943 | PLAY [all]
2025-09-24 00:14:16.109324 | 
2025-09-24 00:14:16.109414 | TASK [Install binary dependencies]
2025-09-24 00:14:16.170117 | controller | ok
2025-09-24 00:14:16.190396 | 
2025-09-24 00:14:16.190486 | TASK [bindep : Include find tasks]
2025-09-24 00:14:16.219994 | controller | ok
2025-09-24 00:14:16.227278 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-24 00:14:16.233443 | 
2025-09-24 00:14:16.233504 | TASK [bindep : Look for bindep.txt]
2025-09-24 00:14:16.752128 | controller | ok
2025-09-24 00:14:16.769144 | 
2025-09-24 00:14:16.769390 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:14:16.799450 | controller | skipping: Conditional result was False
2025-09-24 00:14:16.820719 | 
2025-09-24 00:14:16.820967 | TASK [bindep : Look for other-requirements.txt]
2025-09-24 00:14:17.114245 | controller | ok
2025-09-24 00:14:17.126442 | 
2025-09-24 00:14:17.126589 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:14:17.164632 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.177621 | 
2025-09-24 00:14:17.177812 | TASK [bindep : Look for bindep fallback file]
2025-09-24 00:14:17.205712 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.218392 | 
2025-09-24 00:14:17.218561 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:14:17.247039 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.259896 | 
2025-09-24 00:14:17.260056 | TASK [bindep : Include bindep tasks]
2025-09-24 00:14:17.287835 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.305263 | 
2025-09-24 00:14:17.305491 | TASK [bindep : Include install tasks]
2025-09-24 00:14:17.332959 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.346691 | 
2025-09-24 00:14:17.346835 | LOOP [bindep : Include package tasks]
2025-09-24 00:14:17.411125 | 
2025-09-24 00:14:17.411396 | TASK [Run test-setup role]
2025-09-24 00:14:17.440528 | controller | ok
2025-09-24 00:14:17.471219 | 
2025-09-24 00:14:17.471354 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-24 00:14:17.771546 | controller | ok
2025-09-24 00:14:17.778514 | 
2025-09-24 00:14:17.778587 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-24 00:14:17.913098 | controller | skipping: Conditional result was False
2025-09-24 00:14:17.967923 | 
2025-09-24 00:14:17.968077 | PLAY RECAP
2025-09-24 00:14:17.968140 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-24 00:14:17.968168 | 
2025-09-24 00:14:18.140485 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-24 00:14:18.142341 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-24 00:14:18.787582 | 
2025-09-24 00:14:18.787765 | PLAY [controller]
2025-09-24 00:14:18.807379 | 
2025-09-24 00:14:18.807481 | TASK [Create the /root directory]
2025-09-24 00:14:19.548480 | controller | ok
2025-09-24 00:14:19.561257 | 
2025-09-24 00:14:19.561423 | TASK [Install glibc-langpack-en]
2025-09-24 00:14:27.572307 | controller | ok: Nothing to do
2025-09-24 00:14:27.584449 | 
2025-09-24 00:14:27.584598 | TASK [Ensure controller directory exists]
2025-09-24 00:14:28.055356 | controller | changed
2025-09-24 00:14:28.067624 | 
2025-09-24 00:14:28.067808 | TASK [Install container runtime]
2025-09-24 00:14:28.147380 | controller | ok
2025-09-24 00:14:28.199348 | 
2025-09-24 00:14:28.199496 | LOOP [ensure-podman : Find distribution installation]
2025-09-24 00:14:28.258649 | controller | ok: "/var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-24 00:14:28.267800 | controller | included: /var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-24 00:14:28.274097 | 
2025-09-24 00:14:28.274163 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-24 00:15:48.843038 | controller | changed
2025-09-24 00:15:48.858327 | 
2025-09-24 00:15:48.858475 | TASK [ensure-podman : Fetch podman version]
2025-09-24 00:15:49.643668 | controller | Client:       Podman Engine
2025-09-24 00:15:49.667561 | controller | Version:      4.6.2
2025-09-24 00:15:49.667603 | controller | API Version:  4.6.2
2025-09-24 00:15:49.667610 | controller | Go Version:   go1.19.12
2025-09-24 00:15:49.667628 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-24 00:15:49.667635 | controller | OS/Arch:      linux/amd64
2025-09-24 00:15:50.014425 | controller | ok: Runtime: 0:00:00.195255
2025-09-24 00:15:50.021422 | 
2025-09-24 00:15:50.021532 | TASK [ensure-podman : Print podman version installed]
2025-09-24 00:15:50.062543 | Podman version: Client:       Podman Engine
2025-09-24 00:15:50.062723 | Version:      4.6.2
2025-09-24 00:15:50.062755 | API Version:  4.6.2
2025-09-24 00:15:50.062776 | Go Version:   go1.19.12
2025-09-24 00:15:50.062794 | Built:        Mon Aug 28 19:38:31 2023
2025-09-24 00:15:50.062815 | OS/Arch:      linux/amd64
2025-09-24 00:15:50.068392 | 
2025-09-24 00:15:50.068455 | TASK [ensure-podman : Validate podman engine]
2025-09-24 00:15:50.194782 | controller | skipping: Conditional result was False
2025-09-24 00:15:50.203642 | 
2025-09-24 00:15:50.203751 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-24 00:15:50.229902 | controller | skipping: Conditional result was False
2025-09-24 00:15:50.244635 | 
2025-09-24 00:15:50.244819 | TASK [Ensure python3.8 is present]
2025-09-24 00:15:50.271204 | controller | skipping: Conditional result was False
2025-09-24 00:15:50.279214 | 
2025-09-24 00:15:50.279336 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-24 00:15:50.312800 | controller | ok
2025-09-24 00:15:50.340913 | 
2025-09-24 00:15:50.341072 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-24 00:15:54.329324 | controller | ok: Nothing to do
2025-09-24 00:15:54.336524 | 
2025-09-24 00:15:54.336603 | TASK [our-ensure-python : Also install python3-devel]
2025-09-24 00:16:08.923307 | controller | changed
2025-09-24 00:16:08.946727 | 
2025-09-24 00:16:08.946867 | TASK [Run ensure-virtualenv role]
2025-09-24 00:16:08.970384 | controller | ok
2025-09-24 00:16:08.998543 | 
2025-09-24 00:16:08.998690 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-24 00:16:09.368059 | controller | /usr/bin/virtualenv
2025-09-24 00:16:09.637509 | controller | ok: Runtime: 0:00:00.004867
2025-09-24 00:16:09.650611 | 
2025-09-24 00:16:09.650777 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-24 00:16:09.688750 | controller | skipping: Conditional result was False
2025-09-24 00:16:09.689275 | controller | ok: All items complete
2025-09-24 00:16:09.689335 | 
2025-09-24 00:16:09.715860 | 
2025-09-24 00:16:09.716109 | TASK [Find the full path of the Python interpreter]
2025-09-24 00:16:10.156153 | controller | /usr/bin/python3
2025-09-24 00:16:10.370057 | controller | ok
2025-09-24 00:16:10.381324 | 
2025-09-24 00:16:10.381455 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-24 00:16:11.862936 | controller | created virtual environment CPython3.11.0.final.0-64 in 768ms
2025-09-24 00:16:11.914716 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-24 00:16:11.914774 | 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-24 00:16:11.914793 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-24 00:16:11.914817 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-24 00:16:12.035728 | controller | changed
2025-09-24 00:16:12.042400 | 
2025-09-24 00:16:12.042471 | TASK [Set selinux package]
2025-09-24 00:16:12.072509 | controller | ok
2025-09-24 00:16:12.077411 | 
2025-09-24 00:16:12.077468 | TASK [Set selinux package (Fedora)]
2025-09-24 00:16:12.112703 | controller | ok
2025-09-24 00:16:12.117689 | 
2025-09-24 00:16:12.117764 | TASK [Install selinux into virtualenv]
2025-09-24 00:16:14.711144 | controller | Collecting selinux-please-lie-to-me
2025-09-24 00:16:14.802321 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-24 00:16:15.332471 | controller | Collecting setuptools<50.0.0
2025-09-24 00:16:15.347598 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-24 00:16:15.455742 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.8 MB/s eta 0:00:00
2025-09-24 00:16:15.611841 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-24 00:16:15.612254 | controller |   Attempting uninstall: setuptools
2025-09-24 00:16:15.617293 | controller |     Found existing installation: setuptools 62.6.0
2025-09-24 00:16:15.732337 | controller |     Uninstalling setuptools-62.6.0:
2025-09-24 00:16:15.747930 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-24 00:16:16.506803 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-24 00:16:16.714305 | controller |
2025-09-24 00:16:16.929815 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-24 00:16:16.929867 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-24 00:16:17.311068 | controller | ok: Runtime: 0:00:04.367302
2025-09-24 00:16:17.317064 | 
2025-09-24 00:16:17.317132 | TASK [Install pytest-forked into virtualenv]
2025-09-24 00:16:18.537339 | controller | Collecting pytest-forked
2025-09-24 00:16:18.621907 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-24 00:16:18.682481 | controller | Collecting py
2025-09-24 00:16:18.694860 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-24 00:16:18.727958 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-09-24 00:16:18.906448 | controller | Collecting pytest>=3.10
2025-09-24 00:16:18.918708 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-24 00:16:18.966606 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.2 MB/s eta 0:00:00
2025-09-24 00:16:19.020830 | controller | Collecting iniconfig>=1
2025-09-24 00:16:19.033082 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-24 00:16:19.099517 | controller | Collecting packaging>=20
2025-09-24 00:16:19.111266 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-24 00:16:19.121356 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.7 MB/s eta 0:00:00
2025-09-24 00:16:19.166441 | controller | Collecting pluggy<2,>=1.5
2025-09-24 00:16:19.178203 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-24 00:16:19.251443 | controller | Collecting pygments>=2.7.2
2025-09-24 00:16:19.263545 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-24 00:16:19.357350 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.5 MB/s eta 0:00:00
2025-09-24 00:16:19.488737 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-24 00:16:21.787656 | 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-24 00:16:21.813308 | controller |
2025-09-24 00:16:22.025203 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-24 00:16:22.025256 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-24 00:16:22.492125 | controller | ok: Runtime: 0:00:04.228033
2025-09-24 00:16:22.504716 | 
2025-09-24 00:16:22.504854 | TASK [Update pip]
2025-09-24 00:16:23.658001 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-24 00:16:23.912065 | controller | Collecting pip
2025-09-24 00:16:24.011164 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-24 00:16:24.121607 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 16.5 MB/s eta 0:00:00
2025-09-24 00:16:24.293599 | controller | Installing collected packages: pip
2025-09-24 00:16:24.294498 | controller |   Attempting uninstall: pip
2025-09-24 00:16:24.305739 | controller |     Found existing installation: pip 22.2.2
2025-09-24 00:16:24.594369 | controller |     Uninstalling pip-22.2.2:
2025-09-24 00:16:24.624205 | controller |       Successfully uninstalled pip-22.2.2
2025-09-24 00:16:26.364082 | controller | Successfully installed pip-25.2
2025-09-24 00:16:26.664451 | controller | ok: Runtime: 0:00:03.499346
2025-09-24 00:16:26.677520 | 
2025-09-24 00:16:26.677752 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-24 00:16:27.198023 | controller | changed
2025-09-24 00:16:27.210482 | 
2025-09-24 00:16:27.210724 | TASK [Install ansible into virtualenv]
2025-09-24 00:16:28.278975 | controller | Processing ./src/github.com/ansible/ansible
2025-09-24 00:16:28.285558 | controller |   Installing build dependencies: started
2025-09-24 00:16:30.183755 | controller |   Installing build dependencies: finished with status 'done'
2025-09-24 00:16:31.762364 | controller |   Getting requirements to build wheel: started
2025-09-24 00:16:31.762440 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-24 00:16:31.766769 | controller |   Preparing metadata (pyproject.toml): started
2025-09-24 00:16:32.707746 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-24 00:16:32.712574 | 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-24 00:16:32.717589 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-24 00:16:33.365192 | controller | ERROR
2025-09-24 00:16:33.365468 | controller | {
2025-09-24 00:16:33.365591 | controller |   "delta": "0:00:05.218387",
2025-09-24 00:16:33.365648 | controller |   "end": "2025-09-24 00:16:32.871709",
2025-09-24 00:16:33.365807 | controller |   "msg": "non-zero return code",
2025-09-24 00:16:33.365869 | controller |   "rc": 1,
2025-09-24 00:16:33.365908 | controller |   "start": "2025-09-24 00:16:27.653322"
2025-09-24 00:16:33.365943 | controller | }
failure
2025-09-24 00:16:33.368592 | 
2025-09-24 00:16:33.368754 | PLAY RECAP
2025-09-24 00:16:33.368846 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-24 00:16:33.368893 | 
2025-09-24 00:16:33.497052 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-24 00:16:33.498210 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-24 00:16:34.102178 | 
2025-09-24 00:16:34.102290 | PLAY [all]
2025-09-24 00:16:34.122296 | 
2025-09-24 00:16:34.122375 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-24 00:16:34.857186 | controller | changed: non-zero return code
2025-09-24 00:16:34.862609 | 
2025-09-24 00:16:34.862702 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-24 00:16:34.887340 | controller | skipping: Conditional result was False
2025-09-24 00:16:34.896447 | 
2025-09-24 00:16:34.896552 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-24 00:16:34.932425 | 
2025-09-24 00:16:34.932644 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-24 00:16:34.967113 | 
2025-09-24 00:16:34.967317 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-24 00:16:34.983312 | controller | skipping: Conditional result was False
2025-09-24 00:16:34.992135 | 
2025-09-24 00:16:34.992235 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-24 00:16:35.025349 | 
2025-09-24 00:16:35.025519 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-24 00:16:35.050565 | controller | skipping: Conditional result was False
2025-09-24 00:16:35.057137 | 
2025-09-24 00:16:35.057206 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-24 00:16:35.081833 | controller | skipping: Conditional result was False
2025-09-24 00:16:35.087704 | 
2025-09-24 00:16:35.087770 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-24 00:16:35.112542 | controller | skipping: Conditional result was False
2025-09-24 00:16:35.159761 | 
2025-09-24 00:16:35.159869 | PLAY RECAP
2025-09-24 00:16:35.159949 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-24 00:16:35.159979 | 
2025-09-24 00:16:35.281146 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-24 00:16:35.282063 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-24 00:16:35.890783 | 
2025-09-24 00:16:35.890907 | PLAY [all:!appliance*]
2025-09-24 00:16:35.922346 | 
2025-09-24 00:16:35.922451 | TASK [unregister the node]
2025-09-24 00:16:36.079913 | controller | skipping: Conditional result was False
2025-09-24 00:16:36.086176 | 
2025-09-24 00:16:36.086327 | TASK [include_role : fetch-output]
2025-09-24 00:16:36.127742 | controller | ok
2025-09-24 00:16:36.148403 | 
2025-09-24 00:16:36.148523 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-24 00:16:36.214745 | controller | skipping: Conditional result was False
2025-09-24 00:16:36.227993 | 
2025-09-24 00:16:36.228099 | TASK [fetch-output : Set log path for single node]
2025-09-24 00:16:36.270523 | controller | ok
2025-09-24 00:16:36.277696 | 
2025-09-24 00:16:36.277785 | LOOP [fetch-output : Ensure local output dirs]
2025-09-24 00:16:36.687052 | controller -> localhost | ok: "/var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/logs"
2025-09-24 00:16:36.972238 | controller -> localhost | changed: "/var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/artifacts"
2025-09-24 00:16:37.228498 | controller -> localhost | changed: "/var/lib/zuul/builds/690aec6a84404bee9417f00eb4a78bf5/work/docs"
2025-09-24 00:16:37.256922 | 
2025-09-24 00:16:37.257033 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-24 00:16:38.429725 | controller | changed:
2025-09-24 00:16:38.430064 | controller | .d..t...... ./
2025-09-24 00:16:38.430126 | controller | cd+++++++++ controller/
2025-09-24 00:16:38.430212 | controller | changed: All items complete
2025-09-24 00:16:38.430258 | 
2025-09-24 00:16:39.531752 | controller | changed: .d..t...... ./
2025-09-24 00:16:40.627392 | controller | changed: .d..t...... ./
2025-09-24 00:16:40.659292 | 
2025-09-24 00:16:40.659443 | TASK [include_role : fetch-output-openshift]
2025-09-24 00:16:40.686493 | controller | skipping: Conditional result was False
2025-09-24 00:16:40.699510 | 
2025-09-24 00:16:40.699651 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-24 00:16:40.757326 | controller | skipping: Conditional result was False
2025-09-24 00:16:40.770635 | controller | skipping: Conditional result was False
2025-09-24 00:16:40.836012 | 
2025-09-24 00:16:40.836117 | PLAY [localhost]
2025-09-24 00:16:40.854816 | 
2025-09-24 00:16:40.854901 | TASK [Run Zuul manifest role]
2025-09-24 00:16:40.878366 | localhost | ok
2025-09-24 00:16:40.897386 | 
2025-09-24 00:16:40.897474 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-24 00:16:41.334111 | localhost | changed
2025-09-24 00:16:41.338710 | 
2025-09-24 00:16:41.338821 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-24 00:16:41.377612 | localhost | ok
2025-09-24 00:16:41.386922 | 
2025-09-24 00:16:41.386985 | TASK [Set zuul-log-path fact]
2025-09-24 00:16:41.411246 | localhost | ok
2025-09-24 00:16:41.434916 | 
2025-09-24 00:16:41.435014 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-24 00:16:41.475608 | localhost | ok
2025-09-24 00:16:41.487897 | 
2025-09-24 00:16:41.487981 | LOOP [Run upload-logs-swift role]
2025-09-24 00:16:41.524558 | localhost | Output suppressed because no_log was given
2025-09-24 00:16:41.568498 | 
2025-09-24 00:16:41.568640 | TASK [Set zuul-log-path fact]
2025-09-24 00:16:41.604757 | localhost | skipping: Conditional result was False
2025-09-24 00:16:41.614596 | 
2025-09-24 00:16:41.614781 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-24 00:16:42.118053 | localhost -> localhost | ok: Runtime: 0:00:00.011011
2025-09-24 00:16:42.125983 | 
2025-09-24 00:16:42.126091 | TASK [upload-logs-swift : Upload logs to swift]