2025-10-03 00:13:49.880404 | Job console starting...
2025-10-03 00:13:49.895048 | Updating repositories
2025-10-03 00:13:50.004766 | Preparing job workspace
2025-10-03 00:13:53.569713 | Running Ansible setup...
2025-10-03 00:13:58.313852 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-03 00:13:58.928112 | 
2025-10-03 00:13:58.928256 | PLAY [localhost]
2025-10-03 00:13:58.937148 | 
2025-10-03 00:13:58.937267 | TASK [Gathering Facts]
2025-10-03 00:13:59.995757 | localhost | ok
2025-10-03 00:14:00.021400 | 
2025-10-03 00:14:00.021628 | TASK [Setup log path fact]
2025-10-03 00:14:00.044313 | localhost | ok
2025-10-03 00:14:00.065267 | 
2025-10-03 00:14:00.065426 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 00:14:00.084684 | localhost | ok
2025-10-03 00:14:00.094842 | 
2025-10-03 00:14:00.094962 | TASK [emit-job-header : Print job information]
2025-10-03 00:14:00.124874 | # Job Information
2025-10-03 00:14:00.125037 | Ansible Version: 2.15.12
2025-10-03 00:14:00.125068 | Job: ansible-test-sanity-docker-milestone
2025-10-03 00:14:00.125089 | Pipeline: periodic
2025-10-03 00:14:00.125107 | Executor: ze03.softwarefactory-project.io
2025-10-03 00:14:00.125125 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-03 00:14:00.125146 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/96d/ansible/96d57a75bed64b8885b92db066f73f3e/
2025-10-03 00:14:00.125164 | Event ID: a7a0ce064c7b458f8e369704a2bfb40a
2025-10-03 00:14:00.128815 | 
2025-10-03 00:14:00.129609 | LOOP [emit-job-header : Print node information]
2025-10-03 00:14:00.225323 | localhost | ok:
2025-10-03 00:14:00.225607 | localhost | # Node Information
2025-10-03 00:14:00.225641 | localhost | Inventory Hostname: controller
2025-10-03 00:14:00.225663 | localhost | Hostname: np0005467621
2025-10-03 00:14:00.225682 | localhost | Username: zuul
2025-10-03 00:14:00.225703 | localhost | Distro: Fedora 37
2025-10-03 00:14:00.225721 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-10-03 00:14:00.225758 | localhost | Region: ca-ymq-1
2025-10-03 00:14:00.225777 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-03 00:14:00.225794 | localhost | Product Name: OpenStack Nova
2025-10-03 00:14:00.225813 | localhost | Interface IP: 162.253.55.42
2025-10-03 00:14:00.245609 | 
2025-10-03 00:14:00.245745 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-03 00:14:00.628616 | localhost -> localhost | changed
2025-10-03 00:14:00.634995 | 
2025-10-03 00:14:00.635100 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-03 00:14:01.663530 | localhost -> localhost | changed
2025-10-03 00:14:01.693701 | 
2025-10-03 00:14:01.693837 | PLAY [all:!appliance*]
2025-10-03 00:14:01.718027 | 
2025-10-03 00:14:01.718161 | TASK [include_role : start-zuul-console]
2025-10-03 00:14:01.737586 | controller | ok
2025-10-03 00:14:01.752291 | 
2025-10-03 00:14:01.752413 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-03 00:14:02.137766 | controller | ok
2025-10-03 00:14:02.155635 | 
2025-10-03 00:14:02.155828 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-03 00:14:03.040257 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-03 00:14:03.053560 | 
2025-10-03 00:14:03.053806 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-03 00:14:03.588253 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.607525 | 
2025-10-03 00:14:03.607778 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-03 00:14:03.646097 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.653648 | 
2025-10-03 00:14:03.653824 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-03 00:14:03.690028 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.699456 | 
2025-10-03 00:14:03.699652 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-03 00:14:03.725957 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.733988 | 
2025-10-03 00:14:03.734160 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-03 00:14:03.760749 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.772389 | 
2025-10-03 00:14:03.772570 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-03 00:14:03.808910 | controller | skipping: Conditional result was False
2025-10-03 00:14:03.831365 | 
2025-10-03 00:14:03.831510 | TASK [Disable Fedora Modular]
2025-10-03 00:14:04.088849 | controller | changed
2025-10-03 00:14:04.095991 | 
2025-10-03 00:14:04.096139 | TASK [Enable EPEL]
2025-10-03 00:14:04.122946 | controller | skipping: Conditional result was False
2025-10-03 00:14:04.130833 | 
2025-10-03 00:14:04.130975 | TASK [Register the RHEL node]
2025-10-03 00:14:04.672655 | 
2025-10-03 00:14:04.672887 | TASK [Show the subscription-manager status]
2025-10-03 00:14:05.255560 | controller | skipping: Conditional result was False
2025-10-03 00:14:05.264693 | 
2025-10-03 00:14:05.264847 | TASK [Enable EPEL on RHEL]
2025-10-03 00:14:05.800904 | controller | skipping: Conditional result was False
2025-10-03 00:14:05.814218 | 
2025-10-03 00:14:05.814460 | TASK [Install git and tox]
2025-10-03 00:18:24.866610 | controller | changed
2025-10-03 00:18:24.885178 | 
2025-10-03 00:18:24.885373 | TASK [include_role : prepare-workspace]
2025-10-03 00:18:24.923184 | controller | ok
2025-10-03 00:18:24.958939 | 
2025-10-03 00:18:24.959092 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-03 00:18:25.236262 | controller | ok
2025-10-03 00:18:25.243452 | 
2025-10-03 00:18:25.243532 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-03 00:18:39.502266 | controller | Output suppressed because no_log was given
2025-10-03 00:18:39.513537 | 
2025-10-03 00:18:39.513664 | TASK [include_role : prepare-workspace-openshift]
2025-10-03 00:18:39.538255 | controller | skipping: Conditional result was False
2025-10-03 00:18:39.563965 | 
2025-10-03 00:18:39.564103 | PLAY [all:!appliance]
2025-10-03 00:18:39.583803 | 
2025-10-03 00:18:39.583948 | TASK [Run add-build-sshkey role (RSA)]
2025-10-03 00:18:39.607564 | controller | ok
2025-10-03 00:18:39.629914 | 
2025-10-03 00:18:39.630051 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-03 00:18:39.858430 | controller -> localhost | ok
2025-10-03 00:18:39.864995 | 
2025-10-03 00:18:39.865067 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-03 00:18:39.894961 | controller | ok
2025-10-03 00:18:39.923614 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-03 00:18:39.941138 | 
2025-10-03 00:18:39.941311 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-03 00:18:40.466932 | controller -> localhost | Generating public/private rsa key pair.
2025-10-03 00:18:40.467267 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_rsa.
2025-10-03 00:18:40.467331 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_rsa.pub.
2025-10-03 00:18:40.467375 | controller -> localhost | The key fingerprint is:
2025-10-03 00:18:40.467417 | controller -> localhost | SHA256:nCmt0iFp75OXV5XWfAYPC1xn0Rhp9U2706wlWeiq2d8 zuul-build-sshkey
2025-10-03 00:18:40.467457 | controller -> localhost | The key's randomart image is:
2025-10-03 00:18:40.467496 | controller -> localhost | +---[RSA 2048]----+
2025-10-03 00:18:40.467534 | controller -> localhost | |           . .o*B|
2025-10-03 00:18:40.467574 | controller -> localhost | |            o *==|
2025-10-03 00:18:40.467613 | controller -> localhost | |             o.X+|
2025-10-03 00:18:40.467650 | controller -> localhost | |     . o o   .=+O|
2025-10-03 00:18:40.467687 | controller -> localhost | |    + o S    o++=|
2025-10-03 00:18:40.467772 | controller -> localhost | |   . + +    .. +.|
2025-10-03 00:18:40.467827 | controller -> localhost | |    . +. . .. .  |
2025-10-03 00:18:40.467871 | controller -> localhost | |     oo o .+   . |
2025-10-03 00:18:40.467910 | controller -> localhost | |      .o .o ... E|
2025-10-03 00:18:40.467955 | controller -> localhost | +----[SHA256]-----+
2025-10-03 00:18:40.468046 | controller -> localhost | ok: Runtime: 0:00:00.139894
2025-10-03 00:18:40.483618 | 
2025-10-03 00:18:40.483805 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-03 00:18:40.519643 | controller | ok
2025-10-03 00:18:40.533340 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-03 00:18:40.543381 | 
2025-10-03 00:18:40.543513 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-03 00:18:40.567875 | controller | skipping: Conditional result was False
2025-10-03 00:18:40.574661 | 
2025-10-03 00:18:40.574784 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-03 00:18:41.124716 | controller | changed
2025-10-03 00:18:41.147327 | 
2025-10-03 00:18:41.147515 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-03 00:18:41.387056 | controller | ok
2025-10-03 00:18:41.395247 | 
2025-10-03 00:18:41.395358 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-03 00:18:42.064207 | controller | changed
2025-10-03 00:18:42.073833 | 
2025-10-03 00:18:42.073974 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-03 00:18:42.748453 | controller | changed
2025-10-03 00:18:42.759775 | 
2025-10-03 00:18:42.759941 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-03 00:18:42.788749 | controller | skipping: Conditional result was False
2025-10-03 00:18:42.798652 | 
2025-10-03 00:18:42.798838 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-03 00:18:43.216956 | controller -> localhost | changed
2025-10-03 00:18:43.236686 | 
2025-10-03 00:18:43.236850 | TASK [add-build-sshkey : Add back temp key]
2025-10-03 00:18:43.540380 | controller -> localhost | Identity added: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_rsa (zuul-build-sshkey)
2025-10-03 00:18:43.540839 | controller -> localhost | ok: Runtime: 0:00:00.008629
2025-10-03 00:18:43.552866 | 
2025-10-03 00:18:43.553095 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-03 00:18:43.921308 | controller | ok
2025-10-03 00:18:43.931495 | 
2025-10-03 00:18:43.931648 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-03 00:18:43.962342 | controller | skipping: Conditional result was False
2025-10-03 00:18:43.988791 | 
2025-10-03 00:18:43.988940 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-03 00:18:44.023779 | controller | ok
2025-10-03 00:18:44.048566 | 
2025-10-03 00:18:44.048721 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-03 00:18:44.321152 | controller -> localhost | ok
2025-10-03 00:18:44.348242 | 
2025-10-03 00:18:44.348416 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-03 00:18:44.376487 | controller | ok
2025-10-03 00:18:44.397826 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-03 00:18:44.409994 | 
2025-10-03 00:18:44.410122 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-03 00:18:44.701474 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-03 00:18:44.701675 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_ecdsa.
2025-10-03 00:18:44.701708 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_ecdsa.pub.
2025-10-03 00:18:44.701769 | controller -> localhost | The key fingerprint is:
2025-10-03 00:18:44.701794 | controller -> localhost | SHA256:up6CDehYvDJNithYrOdvGCYCMH04unW87QcgR5OZrmo zuul-build-sshkey
2025-10-03 00:18:44.701822 | controller -> localhost | The key's randomart image is:
2025-10-03 00:18:44.701849 | controller -> localhost | +---[ECDSA 521]---+
2025-10-03 00:18:44.701873 | controller -> localhost | | . . +           |
2025-10-03 00:18:44.701893 | controller -> localhost | |o + B            |
2025-10-03 00:18:44.701913 | controller -> localhost | |.o * .           |
2025-10-03 00:18:44.701937 | controller -> localhost | |o o *            |
2025-10-03 00:18:44.701957 | controller -> localhost | |.* = +  S        |
2025-10-03 00:18:44.701980 | controller -> localhost | |= @ . o.         |
2025-10-03 00:18:44.702009 | controller -> localhost | |*& B ...         |
2025-10-03 00:18:44.702039 | controller -> localhost | |@EB + .o.        |
2025-10-03 00:18:44.702065 | controller -> localhost | |.=.o.o+.         |
2025-10-03 00:18:44.702092 | controller -> localhost | +----[SHA256]-----+
2025-10-03 00:18:44.702153 | controller -> localhost | ok: Runtime: 0:00:00.008805
2025-10-03 00:18:44.709774 | 
2025-10-03 00:18:44.709895 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-03 00:18:44.730886 | controller | ok
2025-10-03 00:18:44.739985 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-03 00:18:44.750136 | 
2025-10-03 00:18:44.750246 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-03 00:18:44.774690 | controller | skipping: Conditional result was False
2025-10-03 00:18:44.781748 | 
2025-10-03 00:18:44.781837 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-03 00:18:45.060640 | controller | changed
2025-10-03 00:18:45.078473 | 
2025-10-03 00:18:45.078664 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-03 00:18:45.322187 | controller | ok
2025-10-03 00:18:45.341036 | 
2025-10-03 00:18:45.341281 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-03 00:18:46.006353 | controller | changed
2025-10-03 00:18:46.021409 | 
2025-10-03 00:18:46.021661 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-03 00:18:46.675853 | controller | changed
2025-10-03 00:18:46.693085 | 
2025-10-03 00:18:46.693306 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-03 00:18:46.804488 | controller | skipping: Conditional result was False
2025-10-03 00:18:46.810433 | 
2025-10-03 00:18:46.810495 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-03 00:18:47.079394 | controller -> localhost | changed
2025-10-03 00:18:47.092085 | 
2025-10-03 00:18:47.092202 | TASK [add-build-sshkey : Add back temp key]
2025-10-03 00:18:47.392995 | controller -> localhost | Identity added: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/96d57a75bed64b8885b92db066f73f3e_id_ecdsa (zuul-build-sshkey)
2025-10-03 00:18:47.393259 | controller -> localhost | ok: Runtime: 0:00:00.008198
2025-10-03 00:18:47.401316 | 
2025-10-03 00:18:47.401414 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-03 00:18:47.625168 | controller | ok
2025-10-03 00:18:47.637780 | 
2025-10-03 00:18:47.637918 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-03 00:18:47.675475 | controller | skipping: Conditional result was False
2025-10-03 00:18:47.703301 | 
2025-10-03 00:18:47.703479 | TASK [include_role : remove-zuul-sshkey]
2025-10-03 00:18:47.731076 | controller | skipping: Conditional result was False
2025-10-03 00:18:47.740041 | 
2025-10-03 00:18:47.740154 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-03 00:18:47.997539 | controller | ok: "logs"
2025-10-03 00:18:47.998047 | controller | ok: All items complete
2025-10-03 00:18:47.998114 | 
2025-10-03 00:18:48.205136 | controller | ok: "artifacts"
2025-10-03 00:18:48.385322 | controller | ok: "docs"
2025-10-03 00:18:48.402853 | 
2025-10-03 00:18:48.403032 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-03 00:18:48.665194 | controller | changed: "logs"
2025-10-03 00:18:48.870194 | controller | changed: "artifacts"
2025-10-03 00:18:49.082098 | controller | changed: "docs"
2025-10-03 00:18:49.116974 | 
2025-10-03 00:18:49.117077 | PLAY RECAP
2025-10-03 00:18:49.117120 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-03 00:18:49.117145 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-03 00:18:49.117162 | 
2025-10-03 00:18:49.248663 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-03 00:18:49.249841 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-03 00:18:49.939439 | 
2025-10-03 00:18:49.939603 | PLAY [all]
2025-10-03 00:18:49.974821 | 
2025-10-03 00:18:49.974999 | TASK [Install binary dependencies]
2025-10-03 00:18:50.037005 | controller | ok
2025-10-03 00:18:50.065111 | 
2025-10-03 00:18:50.065282 | TASK [bindep : Include find tasks]
2025-10-03 00:18:50.099249 | controller | ok
2025-10-03 00:18:50.110738 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-03 00:18:50.117378 | 
2025-10-03 00:18:50.117489 | TASK [bindep : Look for bindep.txt]
2025-10-03 00:18:50.489427 | controller | ok
2025-10-03 00:18:50.499274 | 
2025-10-03 00:18:50.499415 | TASK [bindep : Define bindep_file fact]
2025-10-03 00:18:50.526341 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.534249 | 
2025-10-03 00:18:50.534410 | TASK [bindep : Look for other-requirements.txt]
2025-10-03 00:18:50.760410 | controller | ok
2025-10-03 00:18:50.766558 | 
2025-10-03 00:18:50.766670 | TASK [bindep : Define bindep_file fact]
2025-10-03 00:18:50.791350 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.800141 | 
2025-10-03 00:18:50.800286 | TASK [bindep : Look for bindep fallback file]
2025-10-03 00:18:50.827027 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.837432 | 
2025-10-03 00:18:50.837596 | TASK [bindep : Define bindep_file fact]
2025-10-03 00:18:50.864110 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.872795 | 
2025-10-03 00:18:50.872932 | TASK [bindep : Include bindep tasks]
2025-10-03 00:18:50.898000 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.904321 | 
2025-10-03 00:18:50.904453 | TASK [bindep : Include install tasks]
2025-10-03 00:18:50.928992 | controller | skipping: Conditional result was False
2025-10-03 00:18:50.935514 | 
2025-10-03 00:18:50.935638 | LOOP [bindep : Include package tasks]
2025-10-03 00:18:50.993273 | 
2025-10-03 00:18:50.993443 | TASK [Run test-setup role]
2025-10-03 00:18:51.016183 | controller | ok
2025-10-03 00:18:51.037470 | 
2025-10-03 00:18:51.037645 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-03 00:18:51.268912 | controller | ok
2025-10-03 00:18:51.283722 | 
2025-10-03 00:18:51.283960 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-03 00:18:51.832641 | controller | skipping: Conditional result was False
2025-10-03 00:18:51.876760 | 
2025-10-03 00:18:51.876877 | PLAY RECAP
2025-10-03 00:18:51.876933 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-03 00:18:51.876963 | 
2025-10-03 00:18:52.035866 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-03 00:18:52.036792 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-03 00:18:52.677646 | 
2025-10-03 00:18:52.677812 | PLAY [controller]
2025-10-03 00:18:52.699535 | 
2025-10-03 00:18:52.699692 | TASK [Create the /root directory]
2025-10-03 00:18:53.110741 | controller | ok
2025-10-03 00:18:53.126564 | 
2025-10-03 00:18:53.126747 | TASK [Install glibc-langpack-en]
2025-10-03 00:18:57.201271 | controller | ok: Nothing to do
2025-10-03 00:18:57.207920 | 
2025-10-03 00:18:57.208022 | TASK [Ensure controller directory exists]
2025-10-03 00:18:57.453695 | controller | changed
2025-10-03 00:18:57.471991 | 
2025-10-03 00:18:57.472185 | TASK [Install container runtime]
2025-10-03 00:18:57.544172 | controller | ok
2025-10-03 00:18:57.611023 | 
2025-10-03 00:18:57.611184 | LOOP [ensure-podman : Find distribution installation]
2025-10-03 00:18:57.659218 | controller | ok: "/var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-03 00:18:57.681909 | controller | included: /var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-03 00:18:57.692262 | 
2025-10-03 00:18:57.692417 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-03 00:20:17.070549 | controller | changed
2025-10-03 00:20:17.079663 | 
2025-10-03 00:20:17.079870 | TASK [ensure-podman : Fetch podman version]
2025-10-03 00:20:17.701261 | controller | Client:       Podman Engine
2025-10-03 00:20:17.729711 | controller | Version:      4.6.2
2025-10-03 00:20:17.729739 | controller | API Version:  4.6.2
2025-10-03 00:20:17.729745 | controller | Go Version:   go1.19.12
2025-10-03 00:20:17.729763 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-03 00:20:17.729768 | controller | OS/Arch:      linux/amd64
2025-10-03 00:20:18.116027 | controller | ok: Runtime: 0:00:00.237142
2025-10-03 00:20:18.129466 | 
2025-10-03 00:20:18.129612 | TASK [ensure-podman : Print podman version installed]
2025-10-03 00:20:18.167130 | Podman version: Client:       Podman Engine
2025-10-03 00:20:18.167658 | Version:      4.6.2
2025-10-03 00:20:18.167792 | API Version:  4.6.2
2025-10-03 00:20:18.167890 | Go Version:   go1.19.12
2025-10-03 00:20:18.167935 | Built:        Mon Aug 28 19:38:31 2023
2025-10-03 00:20:18.167983 | OS/Arch:      linux/amd64
2025-10-03 00:20:18.182153 | 
2025-10-03 00:20:18.182362 | TASK [ensure-podman : Validate podman engine]
2025-10-03 00:20:18.723257 | controller | skipping: Conditional result was False
2025-10-03 00:20:18.734463 | 
2025-10-03 00:20:18.734602 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-03 00:20:18.750696 | controller | skipping: Conditional result was False
2025-10-03 00:20:18.764347 | 
2025-10-03 00:20:18.764489 | TASK [Ensure python3.8 is present]
2025-10-03 00:20:18.788917 | controller | skipping: Conditional result was False
2025-10-03 00:20:18.799039 | 
2025-10-03 00:20:18.799161 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-03 00:20:18.821892 | controller | ok
2025-10-03 00:20:18.853420 | 
2025-10-03 00:20:18.853579 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-03 00:20:20.339682 | controller | ok: Nothing to do
2025-10-03 00:20:20.347395 | 
2025-10-03 00:20:20.347559 | TASK [our-ensure-python : Also install python3-devel]
2025-10-03 00:20:30.154326 | controller | changed
2025-10-03 00:20:30.184029 | 
2025-10-03 00:20:30.184275 | TASK [Run ensure-virtualenv role]
2025-10-03 00:20:30.213112 | controller | ok
2025-10-03 00:20:30.256931 | 
2025-10-03 00:20:30.257180 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-03 00:20:30.529828 | controller | /usr/bin/virtualenv
2025-10-03 00:20:30.826363 | controller | ok: Runtime: 0:00:00.005405
2025-10-03 00:20:30.836088 | 
2025-10-03 00:20:30.836268 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-03 00:20:30.888017 | controller | skipping: Conditional result was False
2025-10-03 00:20:30.888418 | controller | ok: All items complete
2025-10-03 00:20:30.888468 | 
2025-10-03 00:20:30.922352 | 
2025-10-03 00:20:30.922532 | TASK [Find the full path of the Python interpreter]
2025-10-03 00:20:31.204325 | controller | /usr/bin/python3
2025-10-03 00:20:31.515054 | controller | ok
2025-10-03 00:20:31.528543 | 
2025-10-03 00:20:31.528806 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-03 00:20:32.390503 | controller | created virtual environment CPython3.11.0.final.0-64 in 449ms
2025-10-03 00:20:32.406720 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-03 00:20:32.406758 | 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/.local/share/virtualenv)
2025-10-03 00:20:32.406767 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-03 00:20:32.406782 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-03 00:20:32.589287 | controller | changed
2025-10-03 00:20:32.595516 | 
2025-10-03 00:20:32.595615 | TASK [Set selinux package]
2025-10-03 00:20:32.636710 | controller | ok
2025-10-03 00:20:32.642274 | 
2025-10-03 00:20:32.642382 | TASK [Set selinux package (Fedora)]
2025-10-03 00:20:32.683143 | controller | ok
2025-10-03 00:20:32.688966 | 
2025-10-03 00:20:32.689092 | TASK [Install selinux into virtualenv]
2025-10-03 00:20:46.638330 | controller | Collecting selinux-please-lie-to-me
2025-10-03 00:20:58.508341 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-03 00:20:58.905584 | controller | Collecting setuptools<50.0.0
2025-10-03 00:20:58.912660 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-03 00:20:58.955576 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 21.7 MB/s eta 0:00:00
2025-10-03 00:20:59.038680 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-03 00:20:59.038939 | controller |   Attempting uninstall: setuptools
2025-10-03 00:20:59.041403 | controller |     Found existing installation: setuptools 62.6.0
2025-10-03 00:20:59.101223 | controller |     Uninstalling setuptools-62.6.0:
2025-10-03 00:20:59.109489 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-03 00:20:59.710168 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-03 00:21:10.875581 | controller |
2025-10-03 00:21:10.963326 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-03 00:21:10.963369 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-03 00:21:11.243818 | controller | ok: Runtime: 0:00:38.057930
2025-10-03 00:21:11.261111 | 
2025-10-03 00:21:11.261342 | TASK [Install pytest-forked into virtualenv]
2025-10-03 00:21:23.118654 | controller | Collecting pytest-forked
2025-10-03 00:21:32.326132 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-03 00:21:32.742718 | controller | Collecting py
2025-10-03 00:21:32.777442 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-03 00:21:32.794787 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.9 MB/s eta 0:00:00
2025-10-03 00:21:33.655431 | controller | Collecting pytest>=3.10
2025-10-03 00:21:33.692268 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-03 00:21:33.710226 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 26.4 MB/s eta 0:00:00
2025-10-03 00:21:33.760721 | controller | Collecting iniconfig>=1
2025-10-03 00:21:33.792085 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-03 00:21:33.854531 | controller | Collecting packaging>=20
2025-10-03 00:21:33.864788 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-03 00:21:33.873826 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 13.5 MB/s eta 0:00:00
2025-10-03 00:21:33.925247 | controller | Collecting pluggy<2,>=1.5
2025-10-03 00:21:33.935947 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-03 00:21:34.030591 | controller | Collecting pygments>=2.7.2
2025-10-03 00:21:34.035331 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-03 00:21:34.057418 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 63.7 MB/s eta 0:00:00
2025-10-03 00:21:34.130202 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-03 00:21:35.184776 | 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-03 00:21:35.194731 | controller |
2025-10-03 00:21:35.266534 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-03 00:21:35.266598 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-03 00:21:35.326659 | controller | ok: Runtime: 0:00:23.780053
2025-10-03 00:21:35.341371 | 
2025-10-03 00:21:35.341582 | TASK [Update pip]
2025-10-03 00:21:35.905529 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-03 00:22:00.296290 | controller | Collecting pip
2025-10-03 00:22:12.482277 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-03 00:22:12.559483 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.3 MB/s eta 0:00:00
2025-10-03 00:22:12.629632 | controller | Installing collected packages: pip
2025-10-03 00:22:12.629830 | controller |   Attempting uninstall: pip
2025-10-03 00:22:12.633009 | controller |     Found existing installation: pip 22.2.2
2025-10-03 00:22:12.782807 | controller |     Uninstalling pip-22.2.2:
2025-10-03 00:22:12.797714 | controller |       Successfully uninstalled pip-22.2.2
2025-10-03 00:22:13.636158 | controller | Successfully installed pip-25.2
2025-10-03 00:22:13.925670 | controller | ok: Runtime: 0:00:38.127143
2025-10-03 00:22:13.932244 | 
2025-10-03 00:22:13.932316 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-03 00:22:14.175238 | controller | changed
2025-10-03 00:22:14.183707 | 
2025-10-03 00:22:14.183872 | TASK [Install ansible into virtualenv]
2025-10-03 00:22:14.809141 | controller | Processing ./src/github.com/ansible/ansible
2025-10-03 00:22:14.812578 | controller |   Installing build dependencies: started
2025-10-03 00:22:37.807829 | controller |   Installing build dependencies: finished with status 'done'
2025-10-03 00:22:37.808437 | controller |   Getting requirements to build wheel: started
2025-10-03 00:22:38.608286 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-03 00:22:38.609121 | controller |   Preparing metadata (pyproject.toml): started
2025-10-03 00:22:39.085196 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-03 00:22:39.090944 | 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-03 00:22:39.095021 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-03 00:22:39.310223 | controller | ERROR
2025-10-03 00:22:39.310493 | controller | {
2025-10-03 00:22:39.310589 | controller |   "delta": "0:00:24.681968",
2025-10-03 00:22:39.310641 | controller |   "end": "2025-10-03 00:22:39.164973",
2025-10-03 00:22:39.310683 | controller |   "msg": "non-zero return code",
2025-10-03 00:22:39.310833 | controller |   "rc": 1,
2025-10-03 00:22:39.310919 | controller |   "start": "2025-10-03 00:22:14.483005"
2025-10-03 00:22:39.310965 | controller | }
failure
2025-10-03 00:22:39.313617 | 
2025-10-03 00:22:39.313716 | PLAY RECAP
2025-10-03 00:22:39.313881 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-03 00:22:39.313932 | 
2025-10-03 00:22:39.449232 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-03 00:22:39.450475 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-03 00:22:40.027584 | 
2025-10-03 00:22:40.027710 | PLAY [all]
2025-10-03 00:22:40.049029 | 
2025-10-03 00:22:40.049132 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-03 00:22:40.302917 | controller | changed: non-zero return code
2025-10-03 00:22:40.312424 | 
2025-10-03 00:22:40.312557 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-03 00:22:40.338348 | controller | skipping: Conditional result was False
2025-10-03 00:22:40.349062 | 
2025-10-03 00:22:40.349187 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-03 00:22:40.385948 | 
2025-10-03 00:22:40.386139 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-03 00:22:40.411153 | 
2025-10-03 00:22:40.411355 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-03 00:22:40.427517 | controller | skipping: Conditional result was False
2025-10-03 00:22:40.439366 | 
2025-10-03 00:22:40.439507 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-03 00:22:40.474789 | 
2025-10-03 00:22:40.474995 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-03 00:22:40.501038 | controller | skipping: Conditional result was False
2025-10-03 00:22:40.511634 | 
2025-10-03 00:22:40.511784 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-03 00:22:40.527414 | controller | skipping: Conditional result was False
2025-10-03 00:22:40.538382 | 
2025-10-03 00:22:40.538520 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-03 00:22:40.565608 | controller | skipping: Conditional result was False
2025-10-03 00:22:40.596798 | 
2025-10-03 00:22:40.596999 | PLAY RECAP
2025-10-03 00:22:40.597055 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-03 00:22:40.597076 | 
2025-10-03 00:22:40.779007 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-03 00:22:40.780021 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-03 00:22:41.370479 | 
2025-10-03 00:22:41.370607 | PLAY [all:!appliance*]
2025-10-03 00:22:41.406564 | 
2025-10-03 00:22:41.406671 | TASK [unregister the node]
2025-10-03 00:22:41.937921 | controller | skipping: Conditional result was False
2025-10-03 00:22:41.946702 | 
2025-10-03 00:22:41.946905 | TASK [include_role : fetch-output]
2025-10-03 00:22:41.985371 | controller | ok
2025-10-03 00:22:42.026461 | 
2025-10-03 00:22:42.026660 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-03 00:22:42.073510 | controller | skipping: Conditional result was False
2025-10-03 00:22:42.081442 | 
2025-10-03 00:22:42.081662 | TASK [fetch-output : Set log path for single node]
2025-10-03 00:22:42.145952 | controller | ok
2025-10-03 00:22:42.152456 | 
2025-10-03 00:22:42.152597 | LOOP [fetch-output : Ensure local output dirs]
2025-10-03 00:22:42.640937 | controller -> localhost | ok: "/var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/logs"
2025-10-03 00:22:42.859784 | controller -> localhost | changed: "/var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/artifacts"
2025-10-03 00:22:43.069484 | controller -> localhost | changed: "/var/lib/zuul/builds/96d57a75bed64b8885b92db066f73f3e/work/docs"
2025-10-03 00:22:43.080956 | 
2025-10-03 00:22:43.081081 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-03 00:22:43.961178 | controller | changed:
2025-10-03 00:22:43.961447 | controller | .d..t...... ./
2025-10-03 00:22:43.961477 | controller | cd+++++++++ controller/
2025-10-03 00:22:43.961512 | controller | changed: All items complete
2025-10-03 00:22:43.961532 | 
2025-10-03 00:22:44.483127 | controller | changed: .d..t...... ./
2025-10-03 00:22:45.017695 | controller | changed: .d..t...... ./
2025-10-03 00:22:45.049510 | 
2025-10-03 00:22:45.049638 | TASK [include_role : fetch-output-openshift]
2025-10-03 00:22:45.085462 | controller | skipping: Conditional result was False
2025-10-03 00:22:45.092692 | 
2025-10-03 00:22:45.092833 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-03 00:22:45.152462 | controller | skipping: Conditional result was False
2025-10-03 00:22:45.155810 | controller | skipping: Conditional result was False
2025-10-03 00:22:45.196960 | 
2025-10-03 00:22:45.197117 | PLAY [localhost]
2025-10-03 00:22:45.223862 | 
2025-10-03 00:22:45.224027 | TASK [Run Zuul manifest role]
2025-10-03 00:22:45.244898 | localhost | ok
2025-10-03 00:22:45.266868 | 
2025-10-03 00:22:45.267069 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-03 00:22:45.745539 | localhost | changed
2025-10-03 00:22:45.755351 | 
2025-10-03 00:22:45.755511 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-03 00:22:45.786319 | localhost | ok
2025-10-03 00:22:45.795516 | 
2025-10-03 00:22:45.795632 | TASK [Set zuul-log-path fact]
2025-10-03 00:22:45.815596 | localhost | ok
2025-10-03 00:22:45.832384 | 
2025-10-03 00:22:45.832694 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 00:22:45.863668 | localhost | ok
2025-10-03 00:22:45.876668 | 
2025-10-03 00:22:45.877085 | LOOP [Run upload-logs-swift role]
2025-10-03 00:22:45.925389 | localhost | Output suppressed because no_log was given
2025-10-03 00:22:45.958535 | 
2025-10-03 00:22:45.958773 | TASK [Set zuul-log-path fact]
2025-10-03 00:22:45.996231 | localhost | skipping: Conditional result was False
2025-10-03 00:22:46.002968 | 
2025-10-03 00:22:46.003061 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-03 00:22:46.536457 | localhost -> localhost | ok: Runtime: 0:00:00.010183
2025-10-03 00:22:46.620606 | 
2025-10-03 00:22:46.620890 | TASK [upload-logs-swift : Upload logs to swift]