2025-09-23 00:11:56.131322 | Job console starting...
2025-09-23 00:11:56.141253 | Updating repositories
2025-09-23 00:11:56.253804 | Preparing job workspace
2025-09-23 00:11:59.865485 | Running Ansible setup...
2025-09-23 00:12:07.790998 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-23 00:12:08.441470 | 
2025-09-23 00:12:08.441608 | PLAY [localhost]
2025-09-23 00:12:08.450683 | 
2025-09-23 00:12:08.450825 | TASK [Gathering Facts]
2025-09-23 00:12:09.467057 | localhost | ok
2025-09-23 00:12:09.484338 | 
2025-09-23 00:12:09.484486 | TASK [Setup log path fact]
2025-09-23 00:12:09.502600 | localhost | ok
2025-09-23 00:12:09.518338 | 
2025-09-23 00:12:09.518457 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-23 00:12:09.556411 | localhost | ok
2025-09-23 00:12:09.564607 | 
2025-09-23 00:12:09.564692 | TASK [emit-job-header : Print job information]
2025-09-23 00:12:09.603470 | # Job Information
2025-09-23 00:12:09.603679 | Ansible Version: 2.15.12
2025-09-23 00:12:09.603715 | Job: ansible-test-sanity-docker-milestone
2025-09-23 00:12:09.603790 | Pipeline: periodic
2025-09-23 00:12:09.603812 | Executor: ze03.softwarefactory-project.io
2025-09-23 00:12:09.603853 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-23 00:12:09.603879 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/4e1/ansible/4e17c34302564726be5bd70663d4cf56/
2025-09-23 00:12:09.603898 | Event ID: ce90a15208884c3e9ebd24fbd880974e
2025-09-23 00:12:09.608603 | 
2025-09-23 00:12:09.608667 | LOOP [emit-job-header : Print node information]
2025-09-23 00:12:09.711142 | localhost | ok:
2025-09-23 00:12:09.711350 | localhost | # Node Information
2025-09-23 00:12:09.711378 | localhost | Inventory Hostname: controller
2025-09-23 00:12:09.711397 | localhost | Hostname: ip-172-16-192-180
2025-09-23 00:12:09.711415 | localhost | Username: zuul-worker
2025-09-23 00:12:09.711434 | localhost | Distro: Fedora 37
2025-09-23 00:12:09.711451 | localhost | Provider: ansible-us-east-2
2025-09-23 00:12:09.711467 | localhost | Region: us-east-2
2025-09-23 00:12:09.711483 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-23 00:12:09.711499 | localhost | Product Name: t3.small
2025-09-23 00:12:09.711515 | localhost | Interface IP: 18.221.23.254
2025-09-23 00:12:09.722307 | 
2025-09-23 00:12:09.722420 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-23 00:12:10.207379 | localhost -> localhost | changed
2025-09-23 00:12:10.213075 | 
2025-09-23 00:12:10.213162 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-23 00:12:11.167377 | localhost -> localhost | changed
2025-09-23 00:12:11.209944 | 
2025-09-23 00:12:11.210047 | PLAY [all:!appliance*]
2025-09-23 00:12:11.243709 | 
2025-09-23 00:12:11.243864 | TASK [include_role : start-zuul-console]
2025-09-23 00:12:11.273864 | controller | ok
2025-09-23 00:12:11.288105 | 
2025-09-23 00:12:11.288234 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-23 00:12:11.965213 | controller | ok
2025-09-23 00:12:11.999244 | 
2025-09-23 00:12:11.999374 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-23 00:12:13.440441 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-23 00:12:13.446874 | 
2025-09-23 00:12:13.446967 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-23 00:12:13.573980 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.582805 | 
2025-09-23 00:12:13.582946 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-23 00:12:13.607936 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.616383 | 
2025-09-23 00:12:13.616521 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-23 00:12:13.641826 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.650405 | 
2025-09-23 00:12:13.650498 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-23 00:12:13.676115 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.684719 | 
2025-09-23 00:12:13.684885 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-23 00:12:13.710206 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.718918 | 
2025-09-23 00:12:13.719071 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-23 00:12:13.744621 | controller | skipping: Conditional result was False
2025-09-23 00:12:13.762306 | 
2025-09-23 00:12:13.762447 | TASK [Disable Fedora Modular]
2025-09-23 00:12:14.501782 | controller | changed
2025-09-23 00:12:14.514936 | 
2025-09-23 00:12:14.515125 | TASK [Enable EPEL]
2025-09-23 00:12:14.531991 | controller | skipping: Conditional result was False
2025-09-23 00:12:14.545955 | 
2025-09-23 00:12:14.546154 | TASK [Register the RHEL node]
2025-09-23 00:12:14.716380 | 
2025-09-23 00:12:14.716667 | TASK [Show the subscription-manager status]
2025-09-23 00:12:14.875265 | controller | skipping: Conditional result was False
2025-09-23 00:12:14.925743 | 
2025-09-23 00:12:14.925855 | TASK [Enable EPEL on RHEL]
2025-09-23 00:12:15.062501 | controller | skipping: Conditional result was False
2025-09-23 00:12:15.068431 | 
2025-09-23 00:12:15.068502 | TASK [Install git and tox]
2025-09-23 00:13:49.731897 | controller | changed
2025-09-23 00:13:49.738952 | 
2025-09-23 00:13:49.739037 | TASK [include_role : prepare-workspace]
2025-09-23 00:13:49.759684 | controller | ok
2025-09-23 00:13:49.780456 | 
2025-09-23 00:13:49.780581 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-23 00:13:50.329469 | controller | ok
2025-09-23 00:13:50.336558 | 
2025-09-23 00:13:50.336637 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-23 00:14:13.634010 | controller | Output suppressed because no_log was given
2025-09-23 00:14:13.644438 | 
2025-09-23 00:14:13.644532 | TASK [include_role : prepare-workspace-openshift]
2025-09-23 00:14:13.659991 | controller | skipping: Conditional result was False
2025-09-23 00:14:13.683048 | 
2025-09-23 00:14:13.683148 | PLAY [all:!appliance]
2025-09-23 00:14:13.732757 | 
2025-09-23 00:14:13.732867 | TASK [Run add-build-sshkey role (RSA)]
2025-09-23 00:14:13.763240 | controller | ok
2025-09-23 00:14:13.778071 | 
2025-09-23 00:14:13.778176 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-23 00:14:14.046195 | controller -> localhost | ok
2025-09-23 00:14:14.053006 | 
2025-09-23 00:14:14.053102 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-23 00:14:14.072987 | controller | ok
2025-09-23 00:14:14.087199 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-23 00:14:14.093059 | 
2025-09-23 00:14:14.093155 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-23 00:14:14.495424 | controller -> localhost | Generating public/private rsa key pair.
2025-09-23 00:14:14.495714 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_rsa.
2025-09-23 00:14:14.496072 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_rsa.pub.
2025-09-23 00:14:14.496131 | controller -> localhost | The key fingerprint is:
2025-09-23 00:14:14.496175 | controller -> localhost | SHA256:icbs1imjtnHAff43qqSTxKq5t3litkOqOzbKjqJkWYU zuul-build-sshkey
2025-09-23 00:14:14.496213 | controller -> localhost | The key's randomart image is:
2025-09-23 00:14:14.496248 | controller -> localhost | +---[RSA 2048]----+
2025-09-23 00:14:14.496283 | controller -> localhost | |                 |
2025-09-23 00:14:14.496319 | controller -> localhost | |    .            |
2025-09-23 00:14:14.496356 | controller -> localhost | |   E .           |
2025-09-23 00:14:14.496391 | controller -> localhost | |   ..+ . .       |
2025-09-23 00:14:14.496426 | controller -> localhost | |   .o.* S        |
2025-09-23 00:14:14.496473 | controller -> localhost | |  o .+o+ .       |
2025-09-23 00:14:14.496519 | controller -> localhost | | + o.o*.=        |
2025-09-23 00:14:14.496559 | controller -> localhost | |Bo..O*+= .  o    |
2025-09-23 00:14:14.496594 | controller -> localhost | |%*=B*B....oo .   |
2025-09-23 00:14:14.496632 | controller -> localhost | +----[SHA256]-----+
2025-09-23 00:14:14.496714 | controller -> localhost | ok: Runtime: 0:00:00.063308
2025-09-23 00:14:14.506239 | 
2025-09-23 00:14:14.506369 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-23 00:14:14.540595 | controller | ok
2025-09-23 00:14:14.555271 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-23 00:14:14.568818 | 
2025-09-23 00:14:14.568951 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-23 00:14:14.594249 | controller | skipping: Conditional result was False
2025-09-23 00:14:14.603510 | 
2025-09-23 00:14:14.603629 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-23 00:14:15.449506 | controller | changed
2025-09-23 00:14:15.463358 | 
2025-09-23 00:14:15.463520 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-23 00:14:15.816422 | controller | ok
2025-09-23 00:14:15.824694 | 
2025-09-23 00:14:15.824838 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-23 00:14:17.141358 | controller | changed
2025-09-23 00:14:17.154970 | 
2025-09-23 00:14:17.155172 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-23 00:14:18.470049 | controller | changed
2025-09-23 00:14:18.476426 | 
2025-09-23 00:14:18.476506 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-23 00:14:18.500994 | controller | skipping: Conditional result was False
2025-09-23 00:14:18.508413 | 
2025-09-23 00:14:18.508492 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-23 00:14:18.930246 | controller -> localhost | changed
2025-09-23 00:14:18.942652 | 
2025-09-23 00:14:18.942782 | TASK [add-build-sshkey : Add back temp key]
2025-09-23 00:14:19.264928 | controller -> localhost | Identity added: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_rsa (zuul-build-sshkey)
2025-09-23 00:14:19.265139 | controller -> localhost | ok: Runtime: 0:00:00.008777
2025-09-23 00:14:19.271677 | 
2025-09-23 00:14:19.271814 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-23 00:14:19.779644 | controller | ok
2025-09-23 00:14:19.785302 | 
2025-09-23 00:14:19.785392 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-23 00:14:19.819430 | controller | skipping: Conditional result was False
2025-09-23 00:14:19.831152 | 
2025-09-23 00:14:19.831253 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-23 00:14:19.862990 | controller | ok
2025-09-23 00:14:19.885158 | 
2025-09-23 00:14:19.885284 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-23 00:14:20.135461 | controller -> localhost | ok
2025-09-23 00:14:20.149988 | 
2025-09-23 00:14:20.150163 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-23 00:14:20.187905 | controller | ok
2025-09-23 00:14:20.207038 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-23 00:14:20.220312 | 
2025-09-23 00:14:20.220505 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-23 00:14:20.514966 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-23 00:14:20.515239 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_ecdsa.
2025-09-23 00:14:20.515294 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_ecdsa.pub.
2025-09-23 00:14:20.515350 | controller -> localhost | The key fingerprint is:
2025-09-23 00:14:20.515391 | controller -> localhost | SHA256:gxDIeJVqYNsREjLYIL6x1qS5j+GYhSMhyriapYwaVYw zuul-build-sshkey
2025-09-23 00:14:20.515429 | controller -> localhost | The key's randomart image is:
2025-09-23 00:14:20.515466 | controller -> localhost | +---[ECDSA 521]---+
2025-09-23 00:14:20.515502 | controller -> localhost | |*B.++.           |
2025-09-23 00:14:20.515539 | controller -> localhost | |Bo*+..           |
2025-09-23 00:14:20.515578 | controller -> localhost | |.=Eo=            |
2025-09-23 00:14:20.515613 | controller -> localhost | | .@o . .         |
2025-09-23 00:14:20.515648 | controller -> localhost | |oB..  . S        |
2025-09-23 00:14:20.515683 | controller -> localhost | |*+.      .       |
2025-09-23 00:14:20.515718 | controller -> localhost | |B+o              |
2025-09-23 00:14:20.515790 | controller -> localhost | |*X+              |
2025-09-23 00:14:20.515828 | controller -> localhost | |%+ .             |
2025-09-23 00:14:20.515863 | controller -> localhost | +----[SHA256]-----+
2025-09-23 00:14:20.515948 | controller -> localhost | ok: Runtime: 0:00:00.016785
2025-09-23 00:14:20.528765 | 
2025-09-23 00:14:20.528892 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-23 00:14:20.551361 | controller | ok
2025-09-23 00:14:20.559357 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-23 00:14:20.568339 | 
2025-09-23 00:14:20.568423 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-23 00:14:20.583267 | controller | skipping: Conditional result was False
2025-09-23 00:14:20.590439 | 
2025-09-23 00:14:20.590550 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-23 00:14:21.046073 | controller | changed
2025-09-23 00:14:21.059364 | 
2025-09-23 00:14:21.059523 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-23 00:14:21.417614 | controller | ok
2025-09-23 00:14:21.430627 | 
2025-09-23 00:14:21.430871 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-23 00:14:22.766694 | controller | changed
2025-09-23 00:14:22.779654 | 
2025-09-23 00:14:22.779845 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-23 00:14:24.083307 | controller | changed
2025-09-23 00:14:24.096271 | 
2025-09-23 00:14:24.096403 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-23 00:14:24.124905 | controller | skipping: Conditional result was False
2025-09-23 00:14:24.139650 | 
2025-09-23 00:14:24.139831 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-23 00:14:24.425603 | controller -> localhost | changed
2025-09-23 00:14:24.447628 | 
2025-09-23 00:14:24.447909 | TASK [add-build-sshkey : Add back temp key]
2025-09-23 00:14:24.799635 | controller -> localhost | Identity added: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/4e17c34302564726be5bd70663d4cf56_id_ecdsa (zuul-build-sshkey)
2025-09-23 00:14:24.800137 | controller -> localhost | ok: Runtime: 0:00:00.009405
2025-09-23 00:14:24.808195 | 
2025-09-23 00:14:24.808314 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-23 00:14:25.364997 | controller | ok
2025-09-23 00:14:25.406280 | 
2025-09-23 00:14:25.406398 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-23 00:14:25.451335 | controller | skipping: Conditional result was False
2025-09-23 00:14:25.463164 | 
2025-09-23 00:14:25.463252 | TASK [include_role : remove-zuul-sshkey]
2025-09-23 00:14:25.487209 | controller | skipping: Conditional result was False
2025-09-23 00:14:25.494293 | 
2025-09-23 00:14:25.494428 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-23 00:14:25.843656 | controller | ok: "logs"
2025-09-23 00:14:25.844341 | controller | ok: All items complete
2025-09-23 00:14:25.844423 | 
2025-09-23 00:14:26.154451 | controller | ok: "artifacts"
2025-09-23 00:14:26.470064 | controller | ok: "docs"
2025-09-23 00:14:26.487140 | 
2025-09-23 00:14:26.487320 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-23 00:14:26.838985 | controller | changed: "logs"
2025-09-23 00:14:27.126948 | controller | changed: "artifacts"
2025-09-23 00:14:27.420672 | controller | changed: "docs"
2025-09-23 00:14:27.458560 | 
2025-09-23 00:14:27.458669 | PLAY RECAP
2025-09-23 00:14:27.458920 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-23 00:14:27.458961 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-23 00:14:27.458986 | 
2025-09-23 00:14:27.572839 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-23 00:14:27.573779 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-23 00:14:28.140452 | 
2025-09-23 00:14:28.140568 | PLAY [all]
2025-09-23 00:14:28.162080 | 
2025-09-23 00:14:28.162211 | TASK [Install binary dependencies]
2025-09-23 00:14:28.214184 | controller | ok
2025-09-23 00:14:28.236495 | 
2025-09-23 00:14:28.236611 | TASK [bindep : Include find tasks]
2025-09-23 00:14:28.267779 | controller | ok
2025-09-23 00:14:28.277200 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-23 00:14:28.286074 | 
2025-09-23 00:14:28.286261 | TASK [bindep : Look for bindep.txt]
2025-09-23 00:14:29.078321 | controller | ok
2025-09-23 00:14:29.092161 | 
2025-09-23 00:14:29.092335 | TASK [bindep : Define bindep_file fact]
2025-09-23 00:14:29.119068 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.132566 | 
2025-09-23 00:14:29.132764 | TASK [bindep : Look for other-requirements.txt]
2025-09-23 00:14:29.477477 | controller | ok
2025-09-23 00:14:29.489700 | 
2025-09-23 00:14:29.489899 | TASK [bindep : Define bindep_file fact]
2025-09-23 00:14:29.516423 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.529191 | 
2025-09-23 00:14:29.529367 | TASK [bindep : Look for bindep fallback file]
2025-09-23 00:14:29.555635 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.567859 | 
2025-09-23 00:14:29.568030 | TASK [bindep : Define bindep_file fact]
2025-09-23 00:14:29.594060 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.600777 | 
2025-09-23 00:14:29.600866 | TASK [bindep : Include bindep tasks]
2025-09-23 00:14:29.624376 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.630341 | 
2025-09-23 00:14:29.630428 | TASK [bindep : Include install tasks]
2025-09-23 00:14:29.653868 | controller | skipping: Conditional result was False
2025-09-23 00:14:29.659501 | 
2025-09-23 00:14:29.659574 | LOOP [bindep : Include package tasks]
2025-09-23 00:14:29.713630 | 
2025-09-23 00:14:29.713803 | TASK [Run test-setup role]
2025-09-23 00:14:29.732522 | controller | ok
2025-09-23 00:14:29.751975 | 
2025-09-23 00:14:29.752102 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-23 00:14:30.129779 | controller | ok
2025-09-23 00:14:30.137815 | 
2025-09-23 00:14:30.137931 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-23 00:14:30.268106 | controller | skipping: Conditional result was False
2025-09-23 00:14:30.301304 | 
2025-09-23 00:14:30.301412 | PLAY RECAP
2025-09-23 00:14:30.301465 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-23 00:14:30.301495 | 
2025-09-23 00:14:30.399068 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-23 00:14:30.400014 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-23 00:14:31.003479 | 
2025-09-23 00:14:31.003656 | PLAY [controller]
2025-09-23 00:14:31.024035 | 
2025-09-23 00:14:31.024165 | TASK [Create the /root directory]
2025-09-23 00:14:31.806812 | controller | ok
2025-09-23 00:14:31.821863 | 
2025-09-23 00:14:31.822081 | TASK [Install glibc-langpack-en]
2025-09-23 00:14:39.867908 | controller | ok: Nothing to do
2025-09-23 00:14:39.873482 | 
2025-09-23 00:14:39.873557 | TASK [Ensure controller directory exists]
2025-09-23 00:14:40.362871 | controller | changed
2025-09-23 00:14:40.368959 | 
2025-09-23 00:14:40.369051 | TASK [Install container runtime]
2025-09-23 00:14:40.419320 | controller | ok
2025-09-23 00:14:40.468801 | 
2025-09-23 00:14:40.468951 | LOOP [ensure-podman : Find distribution installation]
2025-09-23 00:14:40.494372 | controller | ok: "/var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-23 00:14:40.511492 | controller | included: /var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-23 00:14:40.518652 | 
2025-09-23 00:14:40.518811 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-23 00:16:00.765081 | controller | changed
2025-09-23 00:16:00.773915 | 
2025-09-23 00:16:00.774018 | TASK [ensure-podman : Fetch podman version]
2025-09-23 00:16:03.232880 | controller | Client:       Podman Engine
2025-09-23 00:16:03.375622 | controller | Version:      4.6.2
2025-09-23 00:16:03.375893 | controller | API Version:  4.6.2
2025-09-23 00:16:03.375954 | controller | Go Version:   go1.19.12
2025-09-23 00:16:03.376418 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-23 00:16:03.376446 | controller | OS/Arch:      linux/amd64
2025-09-23 00:16:03.915152 | controller | ok: Runtime: 0:00:01.467578
2025-09-23 00:16:03.924575 | 
2025-09-23 00:16:03.924704 | TASK [ensure-podman : Print podman version installed]
2025-09-23 00:16:03.955970 | Podman version: Client:       Podman Engine
2025-09-23 00:16:03.956125 | Version:      4.6.2
2025-09-23 00:16:03.956155 | API Version:  4.6.2
2025-09-23 00:16:03.956177 | Go Version:   go1.19.12
2025-09-23 00:16:03.956195 | Built:        Mon Aug 28 19:38:31 2023
2025-09-23 00:16:03.956215 | OS/Arch:      linux/amd64
2025-09-23 00:16:03.961904 | 
2025-09-23 00:16:03.961973 | TASK [ensure-podman : Validate podman engine]
2025-09-23 00:16:04.091214 | controller | skipping: Conditional result was False
2025-09-23 00:16:04.100806 | 
2025-09-23 00:16:04.100959 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-23 00:16:04.117057 | controller | skipping: Conditional result was False
2025-09-23 00:16:04.133900 | 
2025-09-23 00:16:04.134033 | TASK [Ensure python3.8 is present]
2025-09-23 00:16:04.149533 | controller | skipping: Conditional result was False
2025-09-23 00:16:04.158930 | 
2025-09-23 00:16:04.159050 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-23 00:16:04.180053 | controller | ok
2025-09-23 00:16:04.200829 | 
2025-09-23 00:16:04.200948 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-23 00:16:08.042258 | controller | ok: Nothing to do
2025-09-23 00:16:08.061168 | 
2025-09-23 00:16:08.061303 | TASK [our-ensure-python : Also install python3-devel]
2025-09-23 00:16:21.673474 | controller | changed
2025-09-23 00:16:21.684894 | 
2025-09-23 00:16:21.684992 | TASK [Run ensure-virtualenv role]
2025-09-23 00:16:21.705232 | controller | ok
2025-09-23 00:16:21.728429 | 
2025-09-23 00:16:21.728555 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-23 00:16:22.172972 | controller | /usr/bin/virtualenv
2025-09-23 00:16:22.363582 | controller | ok: Runtime: 0:00:00.015031
2025-09-23 00:16:22.380344 | 
2025-09-23 00:16:22.380496 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-23 00:16:22.405085 | controller | skipping: Conditional result was False
2025-09-23 00:16:22.405380 | controller | ok: All items complete
2025-09-23 00:16:22.405415 | 
2025-09-23 00:16:22.434162 | 
2025-09-23 00:16:22.434390 | TASK [Find the full path of the Python interpreter]
2025-09-23 00:16:22.914479 | controller | /usr/bin/python3
2025-09-23 00:16:23.105191 | controller | ok
2025-09-23 00:16:23.116851 | 
2025-09-23 00:16:23.116999 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-23 00:16:24.618111 | controller | created virtual environment CPython3.11.0.final.0-64 in 779ms
2025-09-23 00:16:24.674368 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-23 00:16:24.674470 | 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-23 00:16:24.674584 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-23 00:16:24.674600 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-23 00:16:24.768979 | controller | changed
2025-09-23 00:16:24.774354 | 
2025-09-23 00:16:24.774416 | TASK [Set selinux package]
2025-09-23 00:16:24.804642 | controller | ok
2025-09-23 00:16:24.811030 | 
2025-09-23 00:16:24.815368 | TASK [Set selinux package (Fedora)]
2025-09-23 00:16:24.856055 | controller | ok
2025-09-23 00:16:24.861283 | 
2025-09-23 00:16:24.861354 | TASK [Install selinux into virtualenv]
2025-09-23 00:16:27.468326 | controller | Collecting selinux-please-lie-to-me
2025-09-23 00:16:27.558243 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-23 00:16:28.090233 | controller | Collecting setuptools<50.0.0
2025-09-23 00:16:28.103859 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-23 00:16:28.238008 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.4 MB/s eta 0:00:00
2025-09-23 00:16:28.393023 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-23 00:16:28.393338 | controller |   Attempting uninstall: setuptools
2025-09-23 00:16:28.398302 | controller |     Found existing installation: setuptools 62.6.0
2025-09-23 00:16:28.510732 | controller |     Uninstalling setuptools-62.6.0:
2025-09-23 00:16:28.526660 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-23 00:16:29.266450 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-23 00:16:29.478355 | controller |
2025-09-23 00:16:29.697790 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-23 00:16:29.697841 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-23 00:16:30.015568 | controller | ok: Runtime: 0:00:04.376797
2025-09-23 00:16:30.023975 | 
2025-09-23 00:16:30.024111 | TASK [Install pytest-forked into virtualenv]
2025-09-23 00:16:31.245915 | controller | Collecting pytest-forked
2025-09-23 00:16:31.337668 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-23 00:16:31.415741 | controller | Collecting py
2025-09-23 00:16:31.429816 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-23 00:16:31.467395 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-09-23 00:16:31.640903 | controller | Collecting pytest>=3.10
2025-09-23 00:16:31.654941 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-23 00:16:31.722334 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.6 MB/s eta 0:00:00
2025-09-23 00:16:31.778100 | controller | Collecting iniconfig>=1
2025-09-23 00:16:31.792361 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-23 00:16:31.859331 | controller | Collecting packaging>=20
2025-09-23 00:16:31.873184 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-23 00:16:31.886660 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.0 MB/s eta 0:00:00
2025-09-23 00:16:31.934709 | controller | Collecting pluggy<2,>=1.5
2025-09-23 00:16:31.948628 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-23 00:16:32.024584 | controller | Collecting pygments>=2.7.2
2025-09-23 00:16:32.038001 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-23 00:16:32.174110 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.2 MB/s eta 0:00:00
2025-09-23 00:16:32.306086 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-23 00:16:34.567893 | 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-23 00:16:34.584344 | controller |
2025-09-23 00:16:34.770150 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-23 00:16:34.770196 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-23 00:16:35.186369 | controller | ok: Runtime: 0:00:04.261709
2025-09-23 00:16:35.196014 | 
2025-09-23 00:16:35.196167 | TASK [Update pip]
2025-09-23 00:16:36.275450 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-23 00:16:36.557633 | controller | Collecting pip
2025-09-23 00:16:36.662231 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-23 00:16:36.839137 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.3 MB/s eta 0:00:00
2025-09-23 00:16:37.004849 | controller | Installing collected packages: pip
2025-09-23 00:16:37.005291 | controller |   Attempting uninstall: pip
2025-09-23 00:16:37.009934 | controller |     Found existing installation: pip 22.2.2
2025-09-23 00:16:37.295910 | controller |     Uninstalling pip-22.2.2:
2025-09-23 00:16:37.325971 | controller |       Successfully uninstalled pip-22.2.2
2025-09-23 00:16:39.078348 | controller | Successfully installed pip-25.2
2025-09-23 00:16:39.366991 | controller | ok: Runtime: 0:00:03.591253
2025-09-23 00:16:39.372634 | 
2025-09-23 00:16:39.372786 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-23 00:16:39.880873 | controller | changed
2025-09-23 00:16:39.893084 | 
2025-09-23 00:16:39.893254 | TASK [Install ansible into virtualenv]
2025-09-23 00:16:41.170970 | controller | Processing ./src/github.com/ansible/ansible
2025-09-23 00:16:41.177382 | controller |   Installing build dependencies: started
2025-09-23 00:16:43.119838 | controller |   Installing build dependencies: finished with status 'done'
2025-09-23 00:16:43.120720 | controller |   Getting requirements to build wheel: started
2025-09-23 00:16:44.678762 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-23 00:16:45.656757 | controller |   Preparing metadata (pyproject.toml): started
2025-09-23 00:16:45.656812 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-23 00:16:45.659059 | 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-23 00:16:45.663961 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-23 00:16:46.075401 | controller | ERROR
2025-09-23 00:16:46.075844 | controller | {
2025-09-23 00:16:46.075948 | controller |   "delta": "0:00:05.374899",
2025-09-23 00:16:46.076017 | controller |   "end": "2025-09-23 00:16:45.811870",
2025-09-23 00:16:46.076079 | controller |   "msg": "non-zero return code",
2025-09-23 00:16:46.076159 | controller |   "rc": 1,
2025-09-23 00:16:46.076218 | controller |   "start": "2025-09-23 00:16:40.436971"
2025-09-23 00:16:46.076276 | controller | }
failure
2025-09-23 00:16:46.080148 | 
2025-09-23 00:16:46.080278 | PLAY RECAP
2025-09-23 00:16:46.080383 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-23 00:16:46.080446 | 
2025-09-23 00:16:46.212402 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-23 00:16:46.213368 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-23 00:16:46.902295 | 
2025-09-23 00:16:46.902550 | PLAY [all]
2025-09-23 00:16:46.924104 | 
2025-09-23 00:16:46.924227 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-23 00:16:47.691031 | controller | changed: non-zero return code
2025-09-23 00:16:47.697017 | 
2025-09-23 00:16:47.697097 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-23 00:16:47.721589 | controller | skipping: Conditional result was False
2025-09-23 00:16:47.730295 | 
2025-09-23 00:16:47.730418 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-23 00:16:47.764953 | 
2025-09-23 00:16:47.765142 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-23 00:16:47.799321 | 
2025-09-23 00:16:47.799516 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-23 00:16:47.816054 | controller | skipping: Conditional result was False
2025-09-23 00:16:47.823094 | 
2025-09-23 00:16:47.823219 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-23 00:16:47.857106 | 
2025-09-23 00:16:47.857310 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-23 00:16:47.872429 | controller | skipping: Conditional result was False
2025-09-23 00:16:47.879359 | 
2025-09-23 00:16:47.879488 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-23 00:16:47.893349 | controller | skipping: Conditional result was False
2025-09-23 00:16:47.899959 | 
2025-09-23 00:16:47.900067 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-23 00:16:47.914166 | controller | skipping: Conditional result was False
2025-09-23 00:16:47.948022 | 
2025-09-23 00:16:47.948130 | PLAY RECAP
2025-09-23 00:16:47.948171 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-23 00:16:47.948193 | 
2025-09-23 00:16:48.063295 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-23 00:16:48.064184 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-23 00:16:48.659463 | 
2025-09-23 00:16:48.659595 | PLAY [all:!appliance*]
2025-09-23 00:16:48.686602 | 
2025-09-23 00:16:48.686747 | TASK [unregister the node]
2025-09-23 00:16:49.099830 | controller | skipping: Conditional result was False
2025-09-23 00:16:49.114910 | 
2025-09-23 00:16:49.115106 | TASK [include_role : fetch-output]
2025-09-23 00:16:49.148490 | controller | ok
2025-09-23 00:16:49.168781 | 
2025-09-23 00:16:49.168936 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-23 00:16:49.213618 | controller | skipping: Conditional result was False
2025-09-23 00:16:49.222040 | 
2025-09-23 00:16:49.222186 | TASK [fetch-output : Set log path for single node]
2025-09-23 00:16:49.253650 | controller | ok
2025-09-23 00:16:49.259228 | 
2025-09-23 00:16:49.259308 | LOOP [fetch-output : Ensure local output dirs]
2025-09-23 00:16:49.699992 | controller -> localhost | ok: "/var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/logs"
2025-09-23 00:16:49.937344 | controller -> localhost | changed: "/var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/artifacts"
2025-09-23 00:16:50.157945 | controller -> localhost | changed: "/var/lib/zuul/builds/4e17c34302564726be5bd70663d4cf56/work/docs"
2025-09-23 00:16:50.171465 | 
2025-09-23 00:16:50.171577 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-23 00:16:51.389120 | controller | changed:
2025-09-23 00:16:51.389348 | controller | .d..t...... ./
2025-09-23 00:16:51.389390 | controller | cd+++++++++ controller/
2025-09-23 00:16:51.389438 | controller | changed: All items complete
2025-09-23 00:16:51.389470 | 
2025-09-23 00:16:52.434227 | controller | changed: .d..t...... ./
2025-09-23 00:16:53.519070 | controller | changed: .d..t...... ./
2025-09-23 00:16:53.555554 | 
2025-09-23 00:16:53.555792 | TASK [include_role : fetch-output-openshift]
2025-09-23 00:16:53.571335 | controller | skipping: Conditional result was False
2025-09-23 00:16:53.580862 | 
2025-09-23 00:16:53.580979 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-23 00:16:53.628717 | controller | skipping: Conditional result was False
2025-09-23 00:16:53.642327 | controller | skipping: Conditional result was False
2025-09-23 00:16:53.689346 | 
2025-09-23 00:16:53.689514 | PLAY [localhost]
2025-09-23 00:16:53.707043 | 
2025-09-23 00:16:53.707140 | TASK [Run Zuul manifest role]
2025-09-23 00:16:53.728121 | localhost | ok
2025-09-23 00:16:53.746932 | 
2025-09-23 00:16:53.747049 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-23 00:16:54.202685 | localhost | changed
2025-09-23 00:16:54.213910 | 
2025-09-23 00:16:54.214184 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-23 00:16:54.251396 | localhost | ok
2025-09-23 00:16:54.270177 | 
2025-09-23 00:16:54.270319 | TASK [Set zuul-log-path fact]
2025-09-23 00:16:54.290192 | localhost | ok
2025-09-23 00:16:54.303890 | 
2025-09-23 00:16:54.303974 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-23 00:16:54.334602 | localhost | ok
2025-09-23 00:16:54.348384 | 
2025-09-23 00:16:54.348493 | LOOP [Run upload-logs-swift role]
2025-09-23 00:16:54.384333 | localhost | Output suppressed because no_log was given
2025-09-23 00:16:54.425189 | 
2025-09-23 00:16:54.425339 | TASK [Set zuul-log-path fact]
2025-09-23 00:16:54.451401 | localhost | skipping: Conditional result was False
2025-09-23 00:16:54.456554 | 
2025-09-23 00:16:54.456629 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-23 00:16:54.919961 | localhost -> localhost | ok: Runtime: 0:00:00.009967
2025-09-23 00:16:54.932229 | 
2025-09-23 00:16:54.932415 | TASK [upload-logs-swift : Upload logs to swift]