2025-10-15 00:20:24.646080 | Job console starting...
2025-10-15 00:20:24.658038 | Updating repositories
2025-10-15 00:20:24.828984 | Preparing job workspace
2025-10-15 00:20:33.727510 | Running Ansible setup...
2025-10-15 00:20:38.862623 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-15 00:20:39.538053 | 
2025-10-15 00:20:39.538198 | PLAY [localhost]
2025-10-15 00:20:39.546715 | 
2025-10-15 00:20:39.546791 | TASK [Gathering Facts]
2025-10-15 00:20:40.576533 | localhost | ok
2025-10-15 00:20:40.606824 | 
2025-10-15 00:20:40.607068 | TASK [Setup log path fact]
2025-10-15 00:20:40.629385 | localhost | ok
2025-10-15 00:20:40.646084 | 
2025-10-15 00:20:40.646188 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-15 00:20:40.688391 | localhost | ok
2025-10-15 00:20:40.704831 | 
2025-10-15 00:20:40.704925 | TASK [emit-job-header : Print job information]
2025-10-15 00:20:40.754544 | # Job Information
2025-10-15 00:20:40.754767 | Ansible Version: 2.15.12
2025-10-15 00:20:40.754812 | Job: ansible-test-sanity-docker-devel
2025-10-15 00:20:40.754841 | Pipeline: periodic
2025-10-15 00:20:40.754868 | Executor: ze02.softwarefactory-project.io
2025-10-15 00:20:40.754894 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-15 00:20:40.754924 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/93a/ansible/93a3725d10a04138ace393b62b172992/
2025-10-15 00:20:40.754951 | Event ID: ef49facc7688412789129926cf599d5c
2025-10-15 00:20:40.759935 | 
2025-10-15 00:20:40.760024 | LOOP [emit-job-header : Print node information]
2025-10-15 00:20:40.893540 | localhost | ok:
2025-10-15 00:20:40.896188 | localhost | # Node Information
2025-10-15 00:20:40.898965 | localhost | Inventory Hostname: controller
2025-10-15 00:20:40.899041 | localhost | Hostname: np0005488296
2025-10-15 00:20:40.899093 | localhost | Username: zuul
2025-10-15 00:20:40.899152 | localhost | Distro: Fedora 37
2025-10-15 00:20:40.899198 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-10-15 00:20:40.899242 | localhost | Region: ca-ymq-1
2025-10-15 00:20:40.899285 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-15 00:20:40.899327 | localhost | Product Name: OpenStack Nova
2025-10-15 00:20:40.899370 | localhost | Interface IP: 199.204.45.242
2025-10-15 00:20:40.916517 | 
2025-10-15 00:20:40.916705 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-15 00:20:41.372830 | localhost -> localhost | changed
2025-10-15 00:20:41.378783 | 
2025-10-15 00:20:41.378873 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-15 00:20:42.484930 | localhost -> localhost | changed
2025-10-15 00:20:42.528037 | 
2025-10-15 00:20:42.528178 | PLAY [all:!appliance*]
2025-10-15 00:20:42.558742 | 
2025-10-15 00:20:42.558864 | TASK [include_role : start-zuul-console]
2025-10-15 00:20:42.582882 | controller | ok
2025-10-15 00:20:42.600656 | 
2025-10-15 00:20:42.600774 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-15 00:20:43.012275 | controller | ok
2025-10-15 00:20:43.033626 | 
2025-10-15 00:20:43.033758 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-15 00:21:05.700372 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-15 00:21:05.714827 | 
2025-10-15 00:21:05.714895 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-15 00:21:06.267560 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.284391 | 
2025-10-15 00:21:06.284559 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-15 00:21:06.321902 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.336983 | 
2025-10-15 00:21:06.337161 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-15 00:21:06.365707 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.380562 | 
2025-10-15 00:21:06.380753 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-15 00:21:06.408745 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.423380 | 
2025-10-15 00:21:06.423559 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-15 00:21:06.451619 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.466845 | 
2025-10-15 00:21:06.467123 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-15 00:21:06.495702 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.524714 | 
2025-10-15 00:21:06.524812 | TASK [Disable Fedora Modular]
2025-10-15 00:21:06.909009 | controller | changed
2025-10-15 00:21:06.922119 | 
2025-10-15 00:21:06.922251 | TASK [Enable EPEL]
2025-10-15 00:21:06.950013 | controller | skipping: Conditional result was False
2025-10-15 00:21:06.964127 | 
2025-10-15 00:21:06.964277 | TASK [Register the RHEL node]
2025-10-15 00:21:07.528476 | 
2025-10-15 00:21:07.528792 | TASK [Show the subscription-manager status]
2025-10-15 00:21:08.082899 | controller | skipping: Conditional result was False
2025-10-15 00:21:08.097037 | 
2025-10-15 00:21:08.097182 | TASK [Enable EPEL on RHEL]
2025-10-15 00:21:08.663965 | controller | skipping: Conditional result was False
2025-10-15 00:21:08.677614 | 
2025-10-15 00:21:08.677781 | TASK [Install git and tox]
2025-10-15 00:22:17.254218 | controller | changed
2025-10-15 00:22:17.267747 | 
2025-10-15 00:22:17.267880 | TASK [include_role : prepare-workspace]
2025-10-15 00:22:17.310203 | controller | ok
2025-10-15 00:22:17.386075 | 
2025-10-15 00:22:17.386219 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-15 00:22:17.639868 | controller | ok
2025-10-15 00:22:17.654890 | 
2025-10-15 00:22:17.655035 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-15 00:22:30.086457 | controller | Output suppressed because no_log was given
2025-10-15 00:22:30.097169 | 
2025-10-15 00:22:30.097254 | TASK [include_role : prepare-workspace-openshift]
2025-10-15 00:22:30.131581 | controller | skipping: Conditional result was False
2025-10-15 00:22:30.157561 | 
2025-10-15 00:22:30.157682 | PLAY [all:!appliance]
2025-10-15 00:22:30.173626 | 
2025-10-15 00:22:30.173755 | TASK [Run add-build-sshkey role (RSA)]
2025-10-15 00:22:30.205836 | controller | ok
2025-10-15 00:22:30.221555 | 
2025-10-15 00:22:30.221633 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-15 00:22:30.470131 | controller -> localhost | ok
2025-10-15 00:22:30.479657 | 
2025-10-15 00:22:30.479777 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-15 00:22:30.518151 | controller | ok
2025-10-15 00:22:30.542335 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-15 00:22:30.551359 | 
2025-10-15 00:22:30.551453 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-15 00:22:31.117587 | controller -> localhost | Generating public/private rsa key pair.
2025-10-15 00:22:31.117845 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_rsa.
2025-10-15 00:22:31.117877 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_rsa.pub.
2025-10-15 00:22:31.117900 | controller -> localhost | The key fingerprint is:
2025-10-15 00:22:31.117934 | controller -> localhost | SHA256:kKyU6qQn0daUl+YAHyCKH/lWf4oSNauh6p5swXM8ycQ zuul-build-sshkey
2025-10-15 00:22:31.117953 | controller -> localhost | The key's randomart image is:
2025-10-15 00:22:31.117971 | controller -> localhost | +---[RSA 2048]----+
2025-10-15 00:22:31.118001 | controller -> localhost | |. o..            |
2025-10-15 00:22:31.118020 | controller -> localhost | |o. + = o         |
2025-10-15 00:22:31.118037 | controller -> localhost | |o + B @          |
2025-10-15 00:22:31.118055 | controller -> localhost | | o E O =         |
2025-10-15 00:22:31.118084 | controller -> localhost | |o X O o S .      |
2025-10-15 00:22:31.118111 | controller -> localhost | | X O + . o       |
2025-10-15 00:22:31.118134 | controller -> localhost | |o B + . .        |
2025-10-15 00:22:31.118153 | controller -> localhost | |.=.  .           |
2025-10-15 00:22:31.118170 | controller -> localhost | |==               |
2025-10-15 00:22:31.118191 | controller -> localhost | +----[SHA256]-----+
2025-10-15 00:22:31.118238 | controller -> localhost | ok: Runtime: 0:00:00.109333
2025-10-15 00:22:31.125609 | 
2025-10-15 00:22:31.125700 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-15 00:22:31.157059 | controller | ok
2025-10-15 00:22:31.175528 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-15 00:22:31.192798 | 
2025-10-15 00:22:31.192938 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-15 00:22:31.217287 | controller | skipping: Conditional result was False
2025-10-15 00:22:31.224462 | 
2025-10-15 00:22:31.224536 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-15 00:22:31.707890 | controller | changed
2025-10-15 00:22:31.720721 | 
2025-10-15 00:22:31.720862 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-15 00:22:31.968603 | controller | ok
2025-10-15 00:22:32.026103 | 
2025-10-15 00:22:32.026314 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-15 00:22:32.717165 | controller | changed
2025-10-15 00:22:32.730461 | 
2025-10-15 00:22:32.730690 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-15 00:22:33.401312 | controller | changed
2025-10-15 00:22:33.416297 | 
2025-10-15 00:22:33.416495 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-15 00:22:33.443856 | controller | skipping: Conditional result was False
2025-10-15 00:22:33.460189 | 
2025-10-15 00:22:33.460322 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-15 00:22:33.914581 | controller -> localhost | changed
2025-10-15 00:22:33.946919 | 
2025-10-15 00:22:33.947102 | TASK [add-build-sshkey : Add back temp key]
2025-10-15 00:22:34.227937 | controller -> localhost | Identity added: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_rsa (zuul-build-sshkey)
2025-10-15 00:22:34.228385 | controller -> localhost | ok: Runtime: 0:00:00.013759
2025-10-15 00:22:34.244002 | 
2025-10-15 00:22:34.244147 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-15 00:22:34.570561 | controller | ok
2025-10-15 00:22:34.575942 | 
2025-10-15 00:22:34.576006 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-15 00:22:34.611116 | controller | skipping: Conditional result was False
2025-10-15 00:22:34.627459 | 
2025-10-15 00:22:34.627549 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-15 00:22:34.648590 | controller | ok
2025-10-15 00:22:34.666251 | 
2025-10-15 00:22:34.666358 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-15 00:22:34.895321 | controller -> localhost | ok
2025-10-15 00:22:34.902078 | 
2025-10-15 00:22:34.902145 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-15 00:22:34.944865 | controller | ok
2025-10-15 00:22:34.960443 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-15 00:22:34.969002 | 
2025-10-15 00:22:34.969200 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-15 00:22:35.273539 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-15 00:22:35.273889 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_ecdsa.
2025-10-15 00:22:35.273950 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_ecdsa.pub.
2025-10-15 00:22:35.274008 | controller -> localhost | The key fingerprint is:
2025-10-15 00:22:35.274053 | controller -> localhost | SHA256:e94IoDNYV1VXoozpFmzjImhf1k+a9mjmx+pSz26rMT8 zuul-build-sshkey
2025-10-15 00:22:35.274098 | controller -> localhost | The key's randomart image is:
2025-10-15 00:22:35.274138 | controller -> localhost | +---[ECDSA 521]---+
2025-10-15 00:22:35.274176 | controller -> localhost | |          ... o..|
2025-10-15 00:22:35.274214 | controller -> localhost | |         o + o . |
2025-10-15 00:22:35.274252 | controller -> localhost | |        . B o    |
2025-10-15 00:22:35.274288 | controller -> localhost | |     . . = o     |
2025-10-15 00:22:35.274326 | controller -> localhost | |    + + S = .    |
2025-10-15 00:22:35.274361 | controller -> localhost | |   + + = +.=     |
2025-10-15 00:22:35.274397 | controller -> localhost | |  . + . o.B+.    |
2025-10-15 00:22:35.274434 | controller -> localhost | |     o  .=oOE    |
2025-10-15 00:22:35.274470 | controller -> localhost | |         *O**o   |
2025-10-15 00:22:35.274506 | controller -> localhost | +----[SHA256]-----+
2025-10-15 00:22:35.274588 | controller -> localhost | ok: Runtime: 0:00:00.015871
2025-10-15 00:22:35.288569 | 
2025-10-15 00:22:35.288803 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-15 00:22:35.319095 | controller | ok
2025-10-15 00:22:35.334977 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-15 00:22:35.350950 | 
2025-10-15 00:22:35.351042 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-15 00:22:35.376846 | controller | skipping: Conditional result was False
2025-10-15 00:22:35.386786 | 
2025-10-15 00:22:35.386887 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-15 00:22:35.718658 | controller | changed
2025-10-15 00:22:35.724428 | 
2025-10-15 00:22:35.724490 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-15 00:22:35.984131 | controller | ok
2025-10-15 00:22:35.997242 | 
2025-10-15 00:22:35.997394 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-15 00:22:36.683452 | controller | changed
2025-10-15 00:22:36.696892 | 
2025-10-15 00:22:36.697088 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-15 00:22:37.381048 | controller | changed
2025-10-15 00:22:37.395130 | 
2025-10-15 00:22:37.395300 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-15 00:22:37.414632 | controller | skipping: Conditional result was False
2025-10-15 00:22:37.430332 | 
2025-10-15 00:22:37.430484 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-15 00:22:37.714430 | controller -> localhost | changed
2025-10-15 00:22:37.727408 | 
2025-10-15 00:22:37.727540 | TASK [add-build-sshkey : Add back temp key]
2025-10-15 00:22:38.048059 | controller -> localhost | Identity added: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/93a3725d10a04138ace393b62b172992_id_ecdsa (zuul-build-sshkey)
2025-10-15 00:22:38.048279 | controller -> localhost | ok: Runtime: 0:00:00.007917
2025-10-15 00:22:38.054989 | 
2025-10-15 00:22:38.055237 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-15 00:22:38.275318 | controller | ok
2025-10-15 00:22:38.287995 | 
2025-10-15 00:22:38.288161 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-15 00:22:38.315836 | controller | skipping: Conditional result was False
2025-10-15 00:22:38.332836 | 
2025-10-15 00:22:38.332969 | TASK [include_role : remove-zuul-sshkey]
2025-10-15 00:22:38.347981 | controller | skipping: Conditional result was False
2025-10-15 00:22:38.357351 | 
2025-10-15 00:22:38.357459 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-15 00:22:38.594044 | controller | ok: "logs"
2025-10-15 00:22:38.594519 | controller | ok: All items complete
2025-10-15 00:22:38.594580 | 
2025-10-15 00:22:38.795033 | controller | ok: "artifacts"
2025-10-15 00:22:39.003047 | controller | ok: "docs"
2025-10-15 00:22:39.015773 | 
2025-10-15 00:22:39.015874 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-15 00:22:39.261440 | controller | changed: "logs"
2025-10-15 00:22:39.462154 | controller | changed: "artifacts"
2025-10-15 00:22:39.670468 | controller | changed: "docs"
2025-10-15 00:22:39.740120 | 
2025-10-15 00:22:39.740232 | PLAY RECAP
2025-10-15 00:22:39.740291 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-15 00:22:39.740327 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-15 00:22:39.740353 | 
2025-10-15 00:22:39.871584 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-15 00:22:39.872505 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-15 00:22:40.510653 | 
2025-10-15 00:22:40.510845 | PLAY [all]
2025-10-15 00:22:40.535368 | 
2025-10-15 00:22:40.535518 | TASK [Install binary dependencies]
2025-10-15 00:22:40.616529 | controller | ok
2025-10-15 00:22:40.637134 | 
2025-10-15 00:22:40.637295 | TASK [bindep : Include find tasks]
2025-10-15 00:22:40.667229 | controller | ok
2025-10-15 00:22:40.675214 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-15 00:22:40.681753 | 
2025-10-15 00:22:40.681835 | TASK [bindep : Look for bindep.txt]
2025-10-15 00:22:41.081744 | controller | ok
2025-10-15 00:22:41.087898 | 
2025-10-15 00:22:41.087968 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:22:41.102291 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.110418 | 
2025-10-15 00:22:41.110524 | TASK [bindep : Look for other-requirements.txt]
2025-10-15 00:22:41.329360 | controller | ok
2025-10-15 00:22:41.342446 | 
2025-10-15 00:22:41.342599 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:22:41.380615 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.395001 | 
2025-10-15 00:22:41.395175 | TASK [bindep : Look for bindep fallback file]
2025-10-15 00:22:41.432483 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.449875 | 
2025-10-15 00:22:41.450072 | TASK [bindep : Define bindep_file fact]
2025-10-15 00:22:41.488419 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.502157 | 
2025-10-15 00:22:41.502297 | TASK [bindep : Include bindep tasks]
2025-10-15 00:22:41.540114 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.555789 | 
2025-10-15 00:22:41.555943 | TASK [bindep : Include install tasks]
2025-10-15 00:22:41.594085 | controller | skipping: Conditional result was False
2025-10-15 00:22:41.611471 | 
2025-10-15 00:22:41.611755 | LOOP [bindep : Include package tasks]
2025-10-15 00:22:41.706130 | 
2025-10-15 00:22:41.706409 | TASK [Run test-setup role]
2025-10-15 00:22:41.738069 | controller | ok
2025-10-15 00:22:41.767148 | 
2025-10-15 00:22:41.767243 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-15 00:22:41.986516 | controller | ok
2025-10-15 00:22:42.000777 | 
2025-10-15 00:22:42.000938 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-15 00:22:42.557658 | controller | skipping: Conditional result was False
2025-10-15 00:22:42.612086 | 
2025-10-15 00:22:42.612165 | PLAY RECAP
2025-10-15 00:22:42.612220 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-15 00:22:42.612250 | 
2025-10-15 00:22:42.750530 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-15 00:22:42.752442 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-15 00:22:43.382899 | 
2025-10-15 00:22:43.383029 | PLAY [controller]
2025-10-15 00:22:43.405121 | 
2025-10-15 00:22:43.405261 | TASK [Create the /root directory]
2025-10-15 00:22:43.853001 | controller | ok
2025-10-15 00:22:43.862142 | 
2025-10-15 00:22:43.862321 | TASK [Install glibc-langpack-en]
2025-10-15 00:22:48.012274 | controller | ok: Nothing to do
2025-10-15 00:22:48.020253 | 
2025-10-15 00:22:48.020341 | TASK [Ensure controller directory exists]
2025-10-15 00:22:48.252736 | controller | changed
2025-10-15 00:22:48.264843 | 
2025-10-15 00:22:48.264946 | TASK [Install container runtime]
2025-10-15 00:22:48.309319 | controller | ok
2025-10-15 00:22:48.352434 | 
2025-10-15 00:22:48.352554 | LOOP [ensure-podman : Find distribution installation]
2025-10-15 00:22:48.381959 | controller | ok: "/var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-15 00:22:48.396312 | controller | included: /var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-15 00:22:48.403491 | 
2025-10-15 00:22:48.403559 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-15 00:23:58.240686 | controller | changed
2025-10-15 00:23:58.260124 | 
2025-10-15 00:23:58.260342 | TASK [ensure-podman : Fetch podman version]
2025-10-15 00:23:58.816455 | controller | Client:       Podman Engine
2025-10-15 00:23:58.851965 | controller | Version:      4.6.2
2025-10-15 00:23:58.852011 | controller | API Version:  4.6.2
2025-10-15 00:23:58.852018 | controller | Go Version:   go1.19.12
2025-10-15 00:23:58.852036 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-15 00:23:58.852045 | controller | OS/Arch:      linux/amd64
2025-10-15 00:23:59.324390 | controller | ok: Runtime: 0:00:00.192851
2025-10-15 00:23:59.337922 | 
2025-10-15 00:23:59.338075 | TASK [ensure-podman : Print podman version installed]
2025-10-15 00:23:59.377206 | Podman version: Client:       Podman Engine
2025-10-15 00:23:59.377443 | Version:      4.6.2
2025-10-15 00:23:59.377504 | API Version:  4.6.2
2025-10-15 00:23:59.377548 | Go Version:   go1.19.12
2025-10-15 00:23:59.377586 | Built:        Mon Aug 28 19:38:31 2023
2025-10-15 00:23:59.377629 | OS/Arch:      linux/amd64
2025-10-15 00:23:59.389973 | 
2025-10-15 00:23:59.390100 | TASK [ensure-podman : Validate podman engine]
2025-10-15 00:23:59.937838 | controller | skipping: Conditional result was False
2025-10-15 00:23:59.951944 | 
2025-10-15 00:23:59.952081 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-15 00:23:59.979342 | controller | skipping: Conditional result was False
2025-10-15 00:24:00.003831 | 
2025-10-15 00:24:00.003970 | TASK [Ensure python3.8 is present]
2025-10-15 00:24:00.031964 | controller | skipping: Conditional result was False
2025-10-15 00:24:00.045387 | 
2025-10-15 00:24:00.045520 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-15 00:24:00.076622 | controller | ok
2025-10-15 00:24:00.105280 | 
2025-10-15 00:24:00.105380 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-15 00:24:01.778031 | controller | ok: Nothing to do
2025-10-15 00:24:01.790220 | 
2025-10-15 00:24:01.790358 | TASK [our-ensure-python : Also install python3-devel]
2025-10-15 00:24:11.782733 | controller | changed
2025-10-15 00:24:11.793337 | 
2025-10-15 00:24:11.793401 | TASK [Run ensure-virtualenv role]
2025-10-15 00:24:11.812548 | controller | ok
2025-10-15 00:24:11.860424 | 
2025-10-15 00:24:11.860560 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-15 00:24:12.106709 | controller | /usr/bin/virtualenv
2025-10-15 00:24:12.390035 | controller | ok: Runtime: 0:00:00.005947
2025-10-15 00:24:12.410032 | 
2025-10-15 00:24:12.410333 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-15 00:24:12.433616 | controller | skipping: Conditional result was False
2025-10-15 00:24:12.433996 | controller | ok: All items complete
2025-10-15 00:24:12.434060 | 
2025-10-15 00:24:12.449080 | 
2025-10-15 00:24:12.449223 | TASK [Find the full path of the Python interpreter]
2025-10-15 00:24:12.654965 | controller | /usr/bin/python3
2025-10-15 00:24:12.979289 | controller | ok
2025-10-15 00:24:12.993447 | 
2025-10-15 00:24:12.993604 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-15 00:24:14.084858 | controller | created virtual environment CPython3.11.0.final.0-64 in 574ms
2025-10-15 00:24:14.101249 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-15 00:24:14.101284 | 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-15 00:24:14.101295 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-15 00:24:14.101309 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-15 00:24:14.553314 | controller | changed
2025-10-15 00:24:14.562640 | 
2025-10-15 00:24:14.562773 | TASK [Set selinux package]
2025-10-15 00:24:14.596186 | controller | ok
2025-10-15 00:24:14.604625 | 
2025-10-15 00:24:14.604730 | TASK [Set selinux package (Fedora)]
2025-10-15 00:24:14.658100 | controller | ok
2025-10-15 00:24:14.665772 | 
2025-10-15 00:24:14.665857 | TASK [Install selinux into virtualenv]
2025-10-15 00:24:28.251229 | controller | Collecting selinux-please-lie-to-me
2025-10-15 00:24:40.527201 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-15 00:24:40.849721 | controller | Collecting setuptools<50.0.0
2025-10-15 00:24:40.854459 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-15 00:24:40.913982 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 14.8 MB/s eta 0:00:00
2025-10-15 00:24:40.995095 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-15 00:24:40.995245 | controller |   Attempting uninstall: setuptools
2025-10-15 00:24:40.997725 | controller |     Found existing installation: setuptools 62.6.0
2025-10-15 00:24:41.056211 | controller |     Uninstalling setuptools-62.6.0:
2025-10-15 00:24:41.063817 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-15 00:24:41.410369 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-15 00:24:52.890524 | controller |
2025-10-15 00:24:52.978312 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-15 00:24:52.978358 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-15 00:24:53.252106 | controller | ok: Runtime: 0:00:38.087575
2025-10-15 00:24:53.265054 | 
2025-10-15 00:24:53.265185 | TASK [Install pytest-forked into virtualenv]
2025-10-15 00:25:05.138214 | controller | Collecting pytest-forked
2025-10-15 00:25:15.333269 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-15 00:25:15.375961 | controller | Collecting py
2025-10-15 00:25:15.379461 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-15 00:25:15.400267 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.6 MB/s eta 0:00:00
2025-10-15 00:25:15.521859 | controller | Collecting pytest>=3.10
2025-10-15 00:25:15.525729 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-15 00:25:15.560404 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 11.9 MB/s eta 0:00:00
2025-10-15 00:25:15.601403 | controller | Collecting iniconfig>=1
2025-10-15 00:25:15.605719 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-15 00:25:15.653342 | controller | Collecting packaging>=20
2025-10-15 00:25:15.656615 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-15 00:25:15.662060 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 20.5 MB/s eta 0:00:00
2025-10-15 00:25:15.691431 | controller | Collecting pluggy<2,>=1.5
2025-10-15 00:25:15.694617 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-15 00:25:15.745481 | controller | Collecting pygments>=2.7.2
2025-10-15 00:25:15.748804 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-15 00:25:15.786471 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 34.4 MB/s eta 0:00:00
2025-10-15 00:25:15.854978 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-15 00:25:17.010815 | 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-15 00:25:17.020078 | controller |
2025-10-15 00:25:17.096134 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-15 00:25:17.096172 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-15 00:25:17.334409 | controller | ok: Runtime: 0:00:23.580142
2025-10-15 00:25:17.388887 | 
2025-10-15 00:25:17.389046 | TASK [Update pip]
2025-10-15 00:25:17.945973 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-15 00:25:30.417225 | controller | Collecting pip
2025-10-15 00:25:42.631076 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-15 00:25:42.706652 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 25.0 MB/s eta 0:00:00
2025-10-15 00:25:42.775302 | controller | Installing collected packages: pip
2025-10-15 00:25:42.775413 | controller |   Attempting uninstall: pip
2025-10-15 00:25:42.777811 | controller |     Found existing installation: pip 22.2.2
2025-10-15 00:25:42.924285 | controller |     Uninstalling pip-22.2.2:
2025-10-15 00:25:42.940098 | controller |       Successfully uninstalled pip-22.2.2
2025-10-15 00:25:43.774668 | controller | Successfully installed pip-25.2
2025-10-15 00:25:43.944199 | controller | ok: Runtime: 0:00:26.250664
2025-10-15 00:25:43.950147 | 
2025-10-15 00:25:43.950239 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-15 00:25:44.174739 | controller | changed
2025-10-15 00:25:44.182363 | 
2025-10-15 00:25:44.182443 | TASK [Install ansible into virtualenv]
2025-10-15 00:25:44.784040 | controller | Processing ./src/github.com/ansible/ansible
2025-10-15 00:25:44.787795 | controller |   Installing build dependencies: started
2025-10-15 00:26:07.617568 | controller |   Installing build dependencies: finished with status 'done'
2025-10-15 00:26:07.618670 | controller |   Getting requirements to build wheel: started
2025-10-15 00:26:08.456940 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-15 00:26:08.459798 | controller |   Preparing metadata (pyproject.toml): started
2025-10-15 00:26:08.986167 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-15 00:26:08.991199 | 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-15 00:26:08.994650 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-15 00:26:09.234630 | controller | ERROR
2025-10-15 00:26:09.234809 | controller | {
2025-10-15 00:26:09.234845 | controller |   "delta": "0:00:24.616345",
2025-10-15 00:26:09.234870 | controller |   "end": "2025-10-15 00:26:09.060175",
2025-10-15 00:26:09.234893 | controller |   "msg": "non-zero return code",
2025-10-15 00:26:09.234927 | controller |   "rc": 1,
2025-10-15 00:26:09.234950 | controller |   "start": "2025-10-15 00:25:44.443830"
2025-10-15 00:26:09.234971 | controller | }
failure
2025-10-15 00:26:09.237003 | 
2025-10-15 00:26:09.237068 | PLAY RECAP
2025-10-15 00:26:09.237124 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-15 00:26:09.237152 | 
2025-10-15 00:26:09.357964 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-15 00:26:09.358952 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-15 00:26:09.932371 | 
2025-10-15 00:26:09.932489 | PLAY [all]
2025-10-15 00:26:09.953464 | 
2025-10-15 00:26:09.953561 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-15 00:26:10.167021 | controller | changed: non-zero return code
2025-10-15 00:26:10.172626 | 
2025-10-15 00:26:10.172733 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-15 00:26:10.187266 | controller | skipping: Conditional result was False
2025-10-15 00:26:10.193785 | 
2025-10-15 00:26:10.193859 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-15 00:26:10.224303 | 
2025-10-15 00:26:10.224456 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-15 00:26:10.274507 | 
2025-10-15 00:26:10.274659 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-15 00:26:10.298445 | controller | skipping: Conditional result was False
2025-10-15 00:26:10.305348 | 
2025-10-15 00:26:10.305414 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-15 00:26:10.341829 | 
2025-10-15 00:26:10.342137 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-15 00:26:10.369482 | controller | skipping: Conditional result was False
2025-10-15 00:26:10.383253 | 
2025-10-15 00:26:10.383406 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-15 00:26:10.400533 | controller | skipping: Conditional result was False
2025-10-15 00:26:10.416102 | 
2025-10-15 00:26:10.416276 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-15 00:26:10.444831 | controller | skipping: Conditional result was False
2025-10-15 00:26:10.496132 | 
2025-10-15 00:26:10.496242 | PLAY RECAP
2025-10-15 00:26:10.496299 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-15 00:26:10.496327 | 
2025-10-15 00:26:10.600855 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-15 00:26:10.602077 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-15 00:26:11.207628 | 
2025-10-15 00:26:11.207783 | PLAY [all:!appliance*]
2025-10-15 00:26:11.229654 | 
2025-10-15 00:26:11.229760 | TASK [unregister the node]
2025-10-15 00:26:11.760851 | controller | skipping: Conditional result was False
2025-10-15 00:26:11.774298 | 
2025-10-15 00:26:11.774460 | TASK [include_role : fetch-output]
2025-10-15 00:26:11.826009 | controller | ok
2025-10-15 00:26:11.858902 | 
2025-10-15 00:26:11.859038 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-15 00:26:11.935938 | controller | skipping: Conditional result was False
2025-10-15 00:26:11.949633 | 
2025-10-15 00:26:11.949809 | TASK [fetch-output : Set log path for single node]
2025-10-15 00:26:12.010940 | controller | ok
2025-10-15 00:26:12.023119 | 
2025-10-15 00:26:12.023255 | LOOP [fetch-output : Ensure local output dirs]
2025-10-15 00:26:12.485794 | controller -> localhost | ok: "/var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/logs"
2025-10-15 00:26:12.749201 | controller -> localhost | changed: "/var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/artifacts"
2025-10-15 00:26:13.012622 | controller -> localhost | changed: "/var/lib/zuul/builds/93a3725d10a04138ace393b62b172992/work/docs"
2025-10-15 00:26:13.035060 | 
2025-10-15 00:26:13.035254 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-15 00:26:13.745599 | controller | changed:
2025-10-15 00:26:13.745991 | controller | .d..t...... ./
2025-10-15 00:26:13.746052 | controller | cd+++++++++ controller/
2025-10-15 00:26:13.746118 | controller | changed: All items complete
2025-10-15 00:26:13.746163 | 
2025-10-15 00:26:14.305539 | controller | changed: .d..t...... ./
2025-10-15 00:26:14.800286 | controller | changed: .d..t...... ./
2025-10-15 00:26:14.838623 | 
2025-10-15 00:26:14.838875 | TASK [include_role : fetch-output-openshift]
2025-10-15 00:26:14.868801 | controller | skipping: Conditional result was False
2025-10-15 00:26:14.887907 | 
2025-10-15 00:26:14.888089 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-15 00:26:14.925330 | controller | skipping: Conditional result was False
2025-10-15 00:26:14.935402 | controller | skipping: Conditional result was False
2025-10-15 00:26:14.977980 | 
2025-10-15 00:26:14.978199 | PLAY [localhost]
2025-10-15 00:26:14.995212 | 
2025-10-15 00:26:14.995299 | TASK [Run Zuul manifest role]
2025-10-15 00:26:15.018525 | localhost | ok
2025-10-15 00:26:15.036176 | 
2025-10-15 00:26:15.036252 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-15 00:26:15.441256 | localhost | changed
2025-10-15 00:26:15.446196 | 
2025-10-15 00:26:15.446260 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-15 00:26:15.476773 | localhost | ok
2025-10-15 00:26:15.484814 | 
2025-10-15 00:26:15.484878 | TASK [Set zuul-log-path fact]
2025-10-15 00:26:15.502648 | localhost | ok
2025-10-15 00:26:15.516982 | 
2025-10-15 00:26:15.517087 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-15 00:26:15.546160 | localhost | ok
2025-10-15 00:26:15.554487 | 
2025-10-15 00:26:15.554548 | LOOP [Run upload-logs-swift role]
2025-10-15 00:26:15.578537 | localhost | Output suppressed because no_log was given
2025-10-15 00:26:15.602459 | 
2025-10-15 00:26:15.602538 | TASK [Set zuul-log-path fact]
2025-10-15 00:26:15.636638 | localhost | skipping: Conditional result was False
2025-10-15 00:26:15.643622 | 
2025-10-15 00:26:15.643711 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-15 00:26:16.076817 | localhost -> localhost | ok: Runtime: 0:00:00.009408
2025-10-15 00:26:16.086947 | 
2025-10-15 00:26:16.087077 | TASK [upload-logs-swift : Upload logs to swift]