2025-10-13 00:06:34.005408 | Job console starting...
2025-10-13 00:06:34.015901 | Updating repositories
2025-10-13 00:06:34.285149 | Preparing job workspace
2025-10-13 00:06:38.691951 | Running Ansible setup...
2025-10-13 00:06:44.698021 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:06:45.320446 | 
2025-10-13 00:06:45.320577 | PLAY [localhost]
2025-10-13 00:06:45.329496 | 
2025-10-13 00:06:45.329593 | TASK [Gathering Facts]
2025-10-13 00:06:46.293186 | localhost | ok
2025-10-13 00:06:46.315023 | 
2025-10-13 00:06:46.315443 | TASK [Setup log path fact]
2025-10-13 00:06:46.334824 | localhost | ok
2025-10-13 00:06:46.348718 | 
2025-10-13 00:06:46.348853 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:06:46.387722 | localhost | ok
2025-10-13 00:06:46.395323 | 
2025-10-13 00:06:46.395410 | TASK [emit-job-header : Print job information]
2025-10-13 00:06:46.444105 | # Job Information
2025-10-13 00:06:46.444257 | Ansible Version: 2.15.12
2025-10-13 00:06:46.444287 | Job: ansible-test-sanity-docker-devel
2025-10-13 00:06:46.444329 | Pipeline: periodic
2025-10-13 00:06:46.444348 | Executor: ze04.softwarefactory-project.io
2025-10-13 00:06:46.444365 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-13 00:06:46.444386 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/0ec/ansible/0ec6a9d5444642c1b75c1bae162863b2/
2025-10-13 00:06:46.444404 | Event ID: 5c3858b4bf9e4fdab660facb3b50ba54
2025-10-13 00:06:46.448258 | 
2025-10-13 00:06:46.448334 | LOOP [emit-job-header : Print node information]
2025-10-13 00:06:46.554210 | localhost | ok:
2025-10-13 00:06:46.554514 | localhost | # Node Information
2025-10-13 00:06:46.554555 | localhost | Inventory Hostname: controller
2025-10-13 00:06:46.554578 | localhost | Hostname: ip-172-16-41-229
2025-10-13 00:06:46.554599 | localhost | Username: zuul-worker
2025-10-13 00:06:46.554622 | localhost | Distro: Fedora 37
2025-10-13 00:06:46.554643 | localhost | Provider: ansible-us-east-2
2025-10-13 00:06:46.554662 | localhost | Region: us-east-2
2025-10-13 00:06:46.554700 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-13 00:06:46.554724 | localhost | Product Name: t3.small
2025-10-13 00:06:46.554743 | localhost | Interface IP: 13.58.141.30
2025-10-13 00:06:46.572427 | 
2025-10-13 00:06:46.572544 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 00:06:47.197036 | localhost -> localhost | changed
2025-10-13 00:06:47.202306 | 
2025-10-13 00:06:47.202371 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 00:06:48.183067 | localhost -> localhost | changed
2025-10-13 00:06:48.209157 | 
2025-10-13 00:06:48.209276 | PLAY [all:!appliance*]
2025-10-13 00:06:48.227980 | 
2025-10-13 00:06:48.228079 | TASK [include_role : start-zuul-console]
2025-10-13 00:06:48.246760 | controller | ok
2025-10-13 00:06:48.260123 | 
2025-10-13 00:06:48.260220 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 00:06:48.932975 | controller | ok
2025-10-13 00:06:48.949236 | 
2025-10-13 00:06:48.949361 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-13 00:06:50.832205 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-13 00:06:50.838536 | 
2025-10-13 00:06:50.838606 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-13 00:06:50.978325 | controller | skipping: Conditional result was False
2025-10-13 00:06:50.992124 | 
2025-10-13 00:06:50.992290 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-13 00:06:51.021165 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.034953 | 
2025-10-13 00:06:51.035087 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-13 00:06:51.060206 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.068844 | 
2025-10-13 00:06:51.068968 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-13 00:06:51.093969 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.103071 | 
2025-10-13 00:06:51.103217 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-13 00:06:51.127835 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.137013 | 
2025-10-13 00:06:51.137182 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-13 00:06:51.154289 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.166602 | 
2025-10-13 00:06:51.166743 | TASK [Disable Fedora Modular]
2025-10-13 00:06:51.869892 | controller | changed
2025-10-13 00:06:51.876017 | 
2025-10-13 00:06:51.876084 | TASK [Enable EPEL]
2025-10-13 00:06:51.901006 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.907943 | 
2025-10-13 00:06:51.908013 | TASK [Register the RHEL node]
2025-10-13 00:06:52.059654 | 
2025-10-13 00:06:52.059799 | TASK [Show the subscription-manager status]
2025-10-13 00:06:52.251212 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.265911 | 
2025-10-13 00:06:52.266070 | TASK [Enable EPEL on RHEL]
2025-10-13 00:06:52.426971 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.440014 | 
2025-10-13 00:06:52.440160 | TASK [Install git and tox]
2025-10-13 00:08:21.341315 | controller | changed
2025-10-13 00:08:21.347471 | 
2025-10-13 00:08:21.347540 | TASK [include_role : prepare-workspace]
2025-10-13 00:08:21.377370 | controller | ok
2025-10-13 00:08:21.405791 | 
2025-10-13 00:08:21.405924 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 00:08:21.933915 | controller | ok
2025-10-13 00:08:21.950111 | 
2025-10-13 00:08:21.950308 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 00:08:35.217932 | controller | Output suppressed because no_log was given
2025-10-13 00:08:35.229900 | 
2025-10-13 00:08:35.229968 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 00:08:35.245555 | controller | skipping: Conditional result was False
2025-10-13 00:08:35.273274 | 
2025-10-13 00:08:35.273369 | PLAY [all:!appliance]
2025-10-13 00:08:35.290934 | 
2025-10-13 00:08:35.291038 | TASK [Run add-build-sshkey role (RSA)]
2025-10-13 00:08:35.330764 | controller | ok
2025-10-13 00:08:35.345549 | 
2025-10-13 00:08:35.345640 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:08:35.573079 | controller -> localhost | ok
2025-10-13 00:08:35.581140 | 
2025-10-13 00:08:35.581223 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:08:35.682290 | controller | ok
2025-10-13 00:08:35.699980 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:08:35.705494 | 
2025-10-13 00:08:35.705554 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:08:36.199058 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 00:08:36.199273 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_rsa.
2025-10-13 00:08:36.199304 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_rsa.pub.
2025-10-13 00:08:36.199326 | controller -> localhost | The key fingerprint is:
2025-10-13 00:08:36.199346 | controller -> localhost | SHA256:fOX1jq4YA5X5zrqo/8hAHDWLXHenJ7UCoOU0G0eRP0s zuul-build-sshkey
2025-10-13 00:08:36.199367 | controller -> localhost | The key's randomart image is:
2025-10-13 00:08:36.199387 | controller -> localhost | +---[RSA 2048]----+
2025-10-13 00:08:36.199406 | controller -> localhost | |        Xo*o. o  |
2025-10-13 00:08:36.199426 | controller -> localhost | |     . O O.= + . |
2025-10-13 00:08:36.199445 | controller -> localhost | |      = + +.= +  |
2025-10-13 00:08:36.199463 | controller -> localhost | |     . o . +E= . |
2025-10-13 00:08:36.199481 | controller -> localhost | |      o S ..oo  .|
2025-10-13 00:08:36.199512 | controller -> localhost | |     .   o o.  o |
2025-10-13 00:08:36.199537 | controller -> localhost | |      .   o o . .|
2025-10-13 00:08:36.199560 | controller -> localhost | |       o o = .   |
2025-10-13 00:08:36.199580 | controller -> localhost | |      .o=.=....  |
2025-10-13 00:08:36.199603 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:08:36.199661 | controller -> localhost | ok: Runtime: 0:00:00.104677
2025-10-13 00:08:36.206636 | 
2025-10-13 00:08:36.206738 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:08:36.226918 | controller | ok
2025-10-13 00:08:36.239239 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:08:36.250004 | 
2025-10-13 00:08:36.250091 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:08:36.264962 | controller | skipping: Conditional result was False
2025-10-13 00:08:36.272819 | 
2025-10-13 00:08:36.272896 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:08:37.001409 | controller | changed
2025-10-13 00:08:37.011895 | 
2025-10-13 00:08:37.012007 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:08:37.357480 | controller | ok
2025-10-13 00:08:37.373774 | 
2025-10-13 00:08:37.373917 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:08:38.779239 | controller | changed
2025-10-13 00:08:38.784975 | 
2025-10-13 00:08:38.785055 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:08:40.167148 | controller | changed
2025-10-13 00:08:40.180875 | 
2025-10-13 00:08:40.181027 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:08:40.209408 | controller | skipping: Conditional result was False
2025-10-13 00:08:40.219789 | 
2025-10-13 00:08:40.219882 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:08:40.571999 | controller -> localhost | changed
2025-10-13 00:08:40.584790 | 
2025-10-13 00:08:40.585308 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:08:40.867334 | controller -> localhost | Identity added: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_rsa (zuul-build-sshkey)
2025-10-13 00:08:40.867565 | controller -> localhost | ok: Runtime: 0:00:00.011867
2025-10-13 00:08:40.873977 | 
2025-10-13 00:08:40.874038 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:08:41.375539 | controller | ok
2025-10-13 00:08:41.387243 | 
2025-10-13 00:08:41.387374 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:08:41.425868 | controller | skipping: Conditional result was False
2025-10-13 00:08:41.450051 | 
2025-10-13 00:08:41.450214 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-13 00:08:41.492034 | controller | ok
2025-10-13 00:08:41.519276 | 
2025-10-13 00:08:41.519378 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:08:41.853728 | controller -> localhost | ok
2025-10-13 00:08:41.860191 | 
2025-10-13 00:08:41.860254 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:08:41.889362 | controller | ok
2025-10-13 00:08:41.905749 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:08:41.919390 | 
2025-10-13 00:08:41.919553 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:08:42.252476 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-13 00:08:42.252632 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_ecdsa.
2025-10-13 00:08:42.252660 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_ecdsa.pub.
2025-10-13 00:08:42.252725 | controller -> localhost | The key fingerprint is:
2025-10-13 00:08:42.252754 | controller -> localhost | SHA256:qT4Rs8hg9ogUFN5h4JiwzB1ubqJgJ8GXe5/Dfrm+VP0 zuul-build-sshkey
2025-10-13 00:08:42.252773 | controller -> localhost | The key's randomart image is:
2025-10-13 00:08:42.252791 | controller -> localhost | +---[ECDSA 521]---+
2025-10-13 00:08:42.252808 | controller -> localhost | |o+o+             |
2025-10-13 00:08:42.252825 | controller -> localhost | |O+= +            |
2025-10-13 00:08:42.252841 | controller -> localhost | |+B.B             |
2025-10-13 00:08:42.252858 | controller -> localhost | | .O . o  .  .    |
2025-10-13 00:08:42.252874 | controller -> localhost | |oB X o +S  . .   |
2025-10-13 00:08:42.252891 | controller -> localhost | |= * = =.. .   .  |
2025-10-13 00:08:42.252907 | controller -> localhost | |.     .* ..    E |
2025-10-13 00:08:42.252924 | controller -> localhost | |     .o oo       |
2025-10-13 00:08:42.252940 | controller -> localhost | |      .oo+o      |
2025-10-13 00:08:42.252956 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:08:42.253003 | controller -> localhost | ok: Runtime: 0:00:00.014201
2025-10-13 00:08:42.259216 | 
2025-10-13 00:08:42.259295 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:08:42.296041 | controller | ok
2025-10-13 00:08:42.307247 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:08:42.319185 | 
2025-10-13 00:08:42.319282 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:08:42.335268 | controller | skipping: Conditional result was False
2025-10-13 00:08:42.345344 | 
2025-10-13 00:08:42.345432 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:08:42.796328 | controller | changed
2025-10-13 00:08:42.807756 | 
2025-10-13 00:08:42.807924 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:08:43.431724 | controller | ok
2025-10-13 00:08:43.444320 | 
2025-10-13 00:08:43.444507 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:08:45.039016 | controller | changed
2025-10-13 00:08:45.053993 | 
2025-10-13 00:08:45.054152 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:08:46.622170 | controller | changed
2025-10-13 00:08:46.631419 | 
2025-10-13 00:08:46.631517 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:08:46.656920 | controller | skipping: Conditional result was False
2025-10-13 00:08:46.666798 | 
2025-10-13 00:08:46.666902 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:08:46.927707 | controller -> localhost | changed
2025-10-13 00:08:46.951796 | 
2025-10-13 00:08:46.951955 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:08:47.284245 | controller -> localhost | Identity added: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/0ec6a9d5444642c1b75c1bae162863b2_id_ecdsa (zuul-build-sshkey)
2025-10-13 00:08:47.284539 | controller -> localhost | ok: Runtime: 0:00:00.014716
2025-10-13 00:08:47.293470 | 
2025-10-13 00:08:47.293568 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:08:47.665872 | controller | ok
2025-10-13 00:08:47.672809 | 
2025-10-13 00:08:47.672894 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:08:47.728276 | controller | skipping: Conditional result was False
2025-10-13 00:08:47.743151 | 
2025-10-13 00:08:47.743257 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 00:08:47.768011 | controller | skipping: Conditional result was False
2025-10-13 00:08:47.786591 | 
2025-10-13 00:08:47.786755 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 00:08:48.154234 | controller | ok: "logs"
2025-10-13 00:08:48.154618 | controller | ok: All items complete
2025-10-13 00:08:48.154674 | 
2025-10-13 00:08:48.486045 | controller | ok: "artifacts"
2025-10-13 00:08:48.966864 | controller | ok: "docs"
2025-10-13 00:08:48.982994 | 
2025-10-13 00:08:48.983088 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 00:08:49.328633 | controller | changed: "logs"
2025-10-13 00:08:49.629170 | controller | changed: "artifacts"
2025-10-13 00:08:49.918534 | controller | changed: "docs"
2025-10-13 00:08:49.959205 | 
2025-10-13 00:08:49.959299 | PLAY RECAP
2025-10-13 00:08:49.959352 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-13 00:08:49.959387 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 00:08:49.959412 | 
2025-10-13 00:08:50.069160 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:08:50.072219 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:08:50.695287 | 
2025-10-13 00:08:50.695419 | PLAY [all]
2025-10-13 00:08:50.719355 | 
2025-10-13 00:08:50.719487 | TASK [Install binary dependencies]
2025-10-13 00:08:50.761275 | controller | ok
2025-10-13 00:08:50.782696 | 
2025-10-13 00:08:50.782834 | TASK [bindep : Include find tasks]
2025-10-13 00:08:50.811962 | controller | ok
2025-10-13 00:08:50.820098 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 00:08:50.826932 | 
2025-10-13 00:08:50.827021 | TASK [bindep : Look for bindep.txt]
2025-10-13 00:08:51.392396 | controller | ok
2025-10-13 00:08:51.408404 | 
2025-10-13 00:08:51.408589 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:08:51.436432 | controller | skipping: Conditional result was False
2025-10-13 00:08:51.453333 | 
2025-10-13 00:08:51.455845 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 00:08:51.772513 | controller | ok
2025-10-13 00:08:51.786412 | 
2025-10-13 00:08:51.786620 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:08:51.825574 | controller | skipping: Conditional result was False
2025-10-13 00:08:51.840864 | 
2025-10-13 00:08:51.841050 | TASK [bindep : Look for bindep fallback file]
2025-10-13 00:08:51.880467 | controller | skipping: Conditional result was False
2025-10-13 00:08:51.893869 | 
2025-10-13 00:08:51.894023 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:08:51.932141 | controller | skipping: Conditional result was False
2025-10-13 00:08:51.947853 | 
2025-10-13 00:08:51.948061 | TASK [bindep : Include bindep tasks]
2025-10-13 00:08:51.976156 | controller | skipping: Conditional result was False
2025-10-13 00:08:51.987200 | 
2025-10-13 00:08:51.987292 | TASK [bindep : Include install tasks]
2025-10-13 00:08:52.012441 | controller | skipping: Conditional result was False
2025-10-13 00:08:52.023292 | 
2025-10-13 00:08:52.023415 | LOOP [bindep : Include package tasks]
2025-10-13 00:08:52.080595 | 
2025-10-13 00:08:52.080788 | TASK [Run test-setup role]
2025-10-13 00:08:52.103218 | controller | ok
2025-10-13 00:08:52.133710 | 
2025-10-13 00:08:52.133840 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 00:08:52.453053 | controller | ok
2025-10-13 00:08:52.464338 | 
2025-10-13 00:08:52.464475 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 00:08:52.632406 | controller | skipping: Conditional result was False
2025-10-13 00:08:52.657989 | 
2025-10-13 00:08:52.658098 | PLAY RECAP
2025-10-13 00:08:52.658149 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:08:52.658176 | 
2025-10-13 00:08:52.766775 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:08:52.769151 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:08:53.404947 | 
2025-10-13 00:08:53.405077 | PLAY [controller]
2025-10-13 00:08:53.426013 | 
2025-10-13 00:08:53.426163 | TASK [Create the /root directory]
2025-10-13 00:08:54.528216 | controller | ok
2025-10-13 00:08:54.536297 | 
2025-10-13 00:08:54.536398 | TASK [Install glibc-langpack-en]
2025-10-13 00:09:02.775072 | controller | ok: Nothing to do
2025-10-13 00:09:02.787594 | 
2025-10-13 00:09:02.787848 | TASK [Ensure controller directory exists]
2025-10-13 00:09:03.201571 | controller | changed
2025-10-13 00:09:03.213087 | 
2025-10-13 00:09:03.213190 | TASK [Install container runtime]
2025-10-13 00:09:03.267330 | controller | ok
2025-10-13 00:09:03.312213 | 
2025-10-13 00:09:03.312331 | LOOP [ensure-podman : Find distribution installation]
2025-10-13 00:09:03.348783 | controller | ok: "/var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-13 00:09:03.369405 | controller | included: /var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-13 00:09:03.379937 | 
2025-10-13 00:09:03.380100 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-13 00:10:16.327200 | controller | changed
2025-10-13 00:10:16.334052 | 
2025-10-13 00:10:16.334140 | TASK [ensure-podman : Fetch podman version]
2025-10-13 00:10:17.056318 | controller | Client:       Podman Engine
2025-10-13 00:10:17.086597 | controller | Version:      4.6.2
2025-10-13 00:10:17.086639 | controller | API Version:  4.6.2
2025-10-13 00:10:17.086646 | controller | Go Version:   go1.19.12
2025-10-13 00:10:17.086663 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:10:17.086670 | controller | OS/Arch:      linux/amd64
2025-10-13 00:10:17.472563 | controller | ok: Runtime: 0:00:00.213363
2025-10-13 00:10:17.481584 | 
2025-10-13 00:10:17.481743 | TASK [ensure-podman : Print podman version installed]
2025-10-13 00:10:17.519841 | Podman version: Client:       Podman Engine
2025-10-13 00:10:17.520019 | Version:      4.6.2
2025-10-13 00:10:17.520053 | API Version:  4.6.2
2025-10-13 00:10:17.520081 | Go Version:   go1.19.12
2025-10-13 00:10:17.520103 | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:10:17.520123 | OS/Arch:      linux/amd64
2025-10-13 00:10:17.526390 | 
2025-10-13 00:10:17.526464 | TASK [ensure-podman : Validate podman engine]
2025-10-13 00:10:17.668203 | controller | skipping: Conditional result was False
2025-10-13 00:10:17.676228 | 
2025-10-13 00:10:17.676352 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-13 00:10:17.690783 | controller | skipping: Conditional result was False
2025-10-13 00:10:17.706081 | 
2025-10-13 00:10:17.706413 | TASK [Ensure python3.8 is present]
2025-10-13 00:10:17.720337 | controller | skipping: Conditional result was False
2025-10-13 00:10:17.727990 | 
2025-10-13 00:10:17.728086 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-13 00:10:17.748816 | controller | ok
2025-10-13 00:10:17.770289 | 
2025-10-13 00:10:17.770408 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-13 00:10:21.484647 | controller | ok: Nothing to do
2025-10-13 00:10:21.498261 | 
2025-10-13 00:10:21.498442 | TASK [our-ensure-python : Also install python3-devel]
2025-10-13 00:10:34.468760 | controller | changed
2025-10-13 00:10:34.479786 | 
2025-10-13 00:10:34.480270 | TASK [Run ensure-virtualenv role]
2025-10-13 00:10:34.499449 | controller | ok
2025-10-13 00:10:34.526770 | 
2025-10-13 00:10:34.526889 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-13 00:10:34.937518 | controller | /usr/bin/virtualenv
2025-10-13 00:10:35.164344 | controller | ok: Runtime: 0:00:00.004446
2025-10-13 00:10:35.177813 | 
2025-10-13 00:10:35.177964 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-13 00:10:35.212881 | controller | skipping: Conditional result was False
2025-10-13 00:10:35.213338 | controller | ok: All items complete
2025-10-13 00:10:35.213406 | 
2025-10-13 00:10:35.248311 | 
2025-10-13 00:10:35.248570 | TASK [Find the full path of the Python interpreter]
2025-10-13 00:10:35.723487 | controller | /usr/bin/python3
2025-10-13 00:10:35.925149 | controller | ok
2025-10-13 00:10:35.935581 | 
2025-10-13 00:10:35.935741 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-13 00:10:37.344774 | controller | created virtual environment CPython3.11.0.final.0-64 in 753ms
2025-10-13 00:10:37.385354 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-13 00:10:37.385413 | 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-13 00:10:37.385432 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-13 00:10:37.385454 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-13 00:10:37.593415 | controller | changed
2025-10-13 00:10:37.607442 | 
2025-10-13 00:10:37.607762 | TASK [Set selinux package]
2025-10-13 00:10:37.637772 | controller | ok
2025-10-13 00:10:37.650913 | 
2025-10-13 00:10:37.651075 | TASK [Set selinux package (Fedora)]
2025-10-13 00:10:37.697305 | controller | ok
2025-10-13 00:10:37.705458 | 
2025-10-13 00:10:37.705578 | TASK [Install selinux into virtualenv]
2025-10-13 00:10:40.323635 | controller | Collecting selinux-please-lie-to-me
2025-10-13 00:10:40.419481 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-13 00:10:40.969377 | controller | Collecting setuptools<50.0.0
2025-10-13 00:10:40.985138 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-13 00:10:41.108169 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.0 MB/s eta 0:00:00
2025-10-13 00:10:41.260674 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-13 00:10:41.260964 | controller |   Attempting uninstall: setuptools
2025-10-13 00:10:41.265838 | controller |     Found existing installation: setuptools 62.6.0
2025-10-13 00:10:41.376797 | controller |     Uninstalling setuptools-62.6.0:
2025-10-13 00:10:41.391931 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-13 00:10:42.127486 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-13 00:10:42.338211 | controller |
2025-10-13 00:10:42.542915 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:10:42.542967 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:10:42.874599 | controller | ok: Runtime: 0:00:04.359118
2025-10-13 00:10:42.887429 | 
2025-10-13 00:10:42.887563 | TASK [Install pytest-forked into virtualenv]
2025-10-13 00:10:44.106897 | controller | Collecting pytest-forked
2025-10-13 00:10:44.190973 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-13 00:10:44.250549 | controller | Collecting py
2025-10-13 00:10:44.263292 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-13 00:10:44.299503 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-13 00:10:44.476178 | controller | Collecting pytest>=3.10
2025-10-13 00:10:44.488904 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-13 00:10:44.552647 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.0 MB/s eta 0:00:00
2025-10-13 00:10:44.606441 | controller | Collecting iniconfig>=1
2025-10-13 00:10:44.618859 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-13 00:10:44.685637 | controller | Collecting packaging>=20
2025-10-13 00:10:44.697530 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-13 00:10:44.709723 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00
2025-10-13 00:10:44.757506 | controller | Collecting pluggy<2,>=1.5
2025-10-13 00:10:44.769246 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-13 00:10:44.841918 | controller | Collecting pygments>=2.7.2
2025-10-13 00:10:44.854215 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-13 00:10:44.981333 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.9 MB/s eta 0:00:00
2025-10-13 00:10:45.117768 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-13 00:10:47.373820 | 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-10-13 00:10:47.389586 | controller |
2025-10-13 00:10:47.567136 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:10:47.567179 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:10:48.064427 | controller | ok: Runtime: 0:00:04.188583
2025-10-13 00:10:48.074892 | 
2025-10-13 00:10:48.074981 | TASK [Update pip]
2025-10-13 00:10:49.173937 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-13 00:10:49.421441 | controller | Collecting pip
2025-10-13 00:10:49.522756 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-13 00:10:49.686879 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.9 MB/s eta 0:00:00
2025-10-13 00:10:49.841859 | controller | Installing collected packages: pip
2025-10-13 00:10:49.842314 | controller |   Attempting uninstall: pip
2025-10-13 00:10:49.846784 | controller |     Found existing installation: pip 22.2.2
2025-10-13 00:10:50.103211 | controller |     Uninstalling pip-22.2.2:
2025-10-13 00:10:50.133113 | controller |       Successfully uninstalled pip-22.2.2
2025-10-13 00:10:51.896148 | controller | Successfully installed pip-25.2
2025-10-13 00:10:52.228169 | controller | ok: Runtime: 0:00:03.502988
2025-10-13 00:10:52.240942 | 
2025-10-13 00:10:52.241211 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-13 00:10:52.765209 | controller | changed
2025-10-13 00:10:52.772311 | 
2025-10-13 00:10:52.772385 | TASK [Install ansible into virtualenv]
2025-10-13 00:10:53.970893 | controller | Processing ./src/github.com/ansible/ansible
2025-10-13 00:10:53.977168 | controller |   Installing build dependencies: started
2025-10-13 00:10:55.928823 | controller |   Installing build dependencies: finished with status 'done'
2025-10-13 00:10:57.454309 | controller |   Getting requirements to build wheel: started
2025-10-13 00:10:57.454368 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-13 00:10:57.455999 | controller |   Preparing metadata (pyproject.toml): started
2025-10-13 00:10:58.391434 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-13 00:10:58.392772 | 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-13 00:10:58.397485 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-13 00:10:58.934789 | controller | ERROR
2025-10-13 00:10:58.935163 | controller | {
2025-10-13 00:10:58.935229 | controller |   "delta": "0:00:05.310755",
2025-10-13 00:10:58.935271 | controller |   "end": "2025-10-13 00:10:58.539529",
2025-10-13 00:10:58.935309 | controller |   "msg": "non-zero return code",
2025-10-13 00:10:58.935372 | controller |   "rc": 1,
2025-10-13 00:10:58.935409 | controller |   "start": "2025-10-13 00:10:53.228774"
2025-10-13 00:10:58.935444 | controller | }
failure
2025-10-13 00:10:58.937895 | 
2025-10-13 00:10:58.937997 | PLAY RECAP
2025-10-13 00:10:58.938085 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-13 00:10:58.938129 | 
2025-10-13 00:10:59.067910 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:10:59.068913 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:10:59.695085 | 
2025-10-13 00:10:59.695218 | PLAY [all]
2025-10-13 00:10:59.729076 | 
2025-10-13 00:10:59.729188 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 00:11:00.558257 | controller | changed: non-zero return code
2025-10-13 00:11:00.570460 | 
2025-10-13 00:11:00.570636 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 00:11:00.597918 | controller | skipping: Conditional result was False
2025-10-13 00:11:00.610178 | 
2025-10-13 00:11:00.610328 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 00:11:00.651514 | 
2025-10-13 00:11:00.651848 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 00:11:00.691725 | 
2025-10-13 00:11:00.691976 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 00:11:00.718835 | controller | skipping: Conditional result was False
2025-10-13 00:11:00.731802 | 
2025-10-13 00:11:00.731951 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 00:11:00.764049 | 
2025-10-13 00:11:00.764308 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 00:11:00.791346 | controller | skipping: Conditional result was False
2025-10-13 00:11:00.803601 | 
2025-10-13 00:11:00.803776 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 00:11:00.830358 | controller | skipping: Conditional result was False
2025-10-13 00:11:00.842663 | 
2025-10-13 00:11:00.842845 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 00:11:00.860055 | controller | skipping: Conditional result was False
2025-10-13 00:11:00.904590 | 
2025-10-13 00:11:00.904712 | PLAY RECAP
2025-10-13 00:11:00.904783 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:11:00.904819 | 
2025-10-13 00:11:01.048954 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:11:01.050644 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-13 00:11:01.681441 | 
2025-10-13 00:11:01.681558 | PLAY [all:!appliance*]
2025-10-13 00:11:01.715667 | 
2025-10-13 00:11:01.715805 | TASK [unregister the node]
2025-10-13 00:11:01.856145 | controller | skipping: Conditional result was False
2025-10-13 00:11:01.862024 | 
2025-10-13 00:11:01.862125 | TASK [include_role : fetch-output]
2025-10-13 00:11:01.892625 | controller | ok
2025-10-13 00:11:01.917048 | 
2025-10-13 00:11:01.917147 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 00:11:01.974170 | controller | skipping: Conditional result was False
2025-10-13 00:11:01.983445 | 
2025-10-13 00:11:01.983570 | TASK [fetch-output : Set log path for single node]
2025-10-13 00:11:02.016436 | controller | ok
2025-10-13 00:11:02.024860 | 
2025-10-13 00:11:02.024955 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 00:11:02.386791 | controller -> localhost | ok: "/var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/logs"
2025-10-13 00:11:02.595835 | controller -> localhost | changed: "/var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/artifacts"
2025-10-13 00:11:02.838531 | controller -> localhost | changed: "/var/lib/zuul/builds/0ec6a9d5444642c1b75c1bae162863b2/work/docs"
2025-10-13 00:11:02.876608 | 
2025-10-13 00:11:02.876897 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 00:11:04.271482 | controller | changed:
2025-10-13 00:11:04.271869 | controller | .d..t...... ./
2025-10-13 00:11:04.271935 | controller | cd+++++++++ controller/
2025-10-13 00:11:04.272002 | controller | changed: All items complete
2025-10-13 00:11:04.272046 | 
2025-10-13 00:11:05.359759 | controller | changed: .d..t...... ./
2025-10-13 00:11:06.491352 | controller | changed: .d..t...... ./
2025-10-13 00:11:06.528475 | 
2025-10-13 00:11:06.528711 | TASK [include_role : fetch-output-openshift]
2025-10-13 00:11:06.556616 | controller | skipping: Conditional result was False
2025-10-13 00:11:06.570086 | 
2025-10-13 00:11:06.570237 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 00:11:06.612780 | controller | skipping: Conditional result was False
2025-10-13 00:11:06.625714 | controller | skipping: Conditional result was False
2025-10-13 00:11:06.661553 | 
2025-10-13 00:11:06.661754 | PLAY [localhost]
2025-10-13 00:11:06.674119 | 
2025-10-13 00:11:06.674195 | TASK [Run Zuul manifest role]
2025-10-13 00:11:06.693127 | localhost | ok
2025-10-13 00:11:06.706407 | 
2025-10-13 00:11:06.706479 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 00:11:07.154068 | localhost | changed
2025-10-13 00:11:07.160344 | 
2025-10-13 00:11:07.160425 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 00:11:07.190700 | localhost | ok
2025-10-13 00:11:07.201894 | 
2025-10-13 00:11:07.201977 | TASK [Set zuul-log-path fact]
2025-10-13 00:11:07.222134 | localhost | ok
2025-10-13 00:11:07.241254 | 
2025-10-13 00:11:07.241350 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:11:07.271722 | localhost | ok
2025-10-13 00:11:07.284233 | 
2025-10-13 00:11:07.284316 | LOOP [Run upload-logs-swift role]
2025-10-13 00:11:07.319461 | localhost | Output suppressed because no_log was given
2025-10-13 00:11:07.354113 | 
2025-10-13 00:11:07.354208 | TASK [Set zuul-log-path fact]
2025-10-13 00:11:07.379829 | localhost | skipping: Conditional result was False
2025-10-13 00:11:07.386633 | 
2025-10-13 00:11:07.386850 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-13 00:11:07.839905 | localhost -> localhost | ok: Runtime: 0:00:00.009734
2025-10-13 00:11:07.853327 | 
2025-10-13 00:11:07.853476 | TASK [upload-logs-swift : Upload logs to swift]