2025-10-24 00:06:39.146565 | Job console starting...
2025-10-24 00:06:39.155984 | Updating repositories
2025-10-24 00:06:39.482236 | Preparing job workspace
2025-10-24 00:06:44.066599 | Running Ansible setup...
2025-10-24 00:06:49.837890 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-24 00:06:50.608841 | 
2025-10-24 00:06:50.608990 | PLAY [localhost]
2025-10-24 00:06:50.635474 | 
2025-10-24 00:06:50.635621 | TASK [Gathering Facts]
2025-10-24 00:06:51.627606 | localhost | ok
2025-10-24 00:06:51.641955 | 
2025-10-24 00:06:51.642072 | TASK [Setup log path fact]
2025-10-24 00:06:51.660317 | localhost | ok
2025-10-24 00:06:51.673275 | 
2025-10-24 00:06:51.673353 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-24 00:06:51.706583 | localhost | ok
2025-10-24 00:06:51.721834 | 
2025-10-24 00:06:51.721939 | TASK [emit-job-header : Print job information]
2025-10-24 00:06:51.753222 | # Job Information
2025-10-24 00:06:51.753380 | Ansible Version: 2.15.12
2025-10-24 00:06:51.753412 | Job: ansible-test-sanity-docker-milestone
2025-10-24 00:06:51.753433 | Pipeline: periodic
2025-10-24 00:06:51.753452 | Executor: ze01.softwarefactory-project.io
2025-10-24 00:06:51.753471 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-24 00:06:51.753493 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/dc2/ansible/dc27d2e9a6e741ada6a880d758b638f9/
2025-10-24 00:06:51.753512 | Event ID: acb2b6be1cf84e53ab9a0343da01d887
2025-10-24 00:06:51.757294 | 
2025-10-24 00:06:51.757361 | LOOP [emit-job-header : Print node information]
2025-10-24 00:06:51.855558 | localhost | ok:
2025-10-24 00:06:51.855765 | localhost | # Node Information
2025-10-24 00:06:51.855793 | localhost | Inventory Hostname: controller
2025-10-24 00:06:51.855812 | localhost | Hostname: np0005500885
2025-10-24 00:06:51.855831 | localhost | Username: zuul
2025-10-24 00:06:51.855855 | localhost | Distro: Fedora 37
2025-10-24 00:06:51.855874 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-10-24 00:06:51.855891 | localhost | Region: ca-ymq-1
2025-10-24 00:06:51.855908 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-24 00:06:51.855924 | localhost | Product Name: OpenStack Nova
2025-10-24 00:06:51.855941 | localhost | Interface IP: 162.253.55.221
2025-10-24 00:06:51.870440 | 
2025-10-24 00:06:51.870542 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-24 00:06:52.322897 | localhost -> localhost | changed
2025-10-24 00:06:52.328896 | 
2025-10-24 00:06:52.328966 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-24 00:06:53.368765 | localhost -> localhost | changed
2025-10-24 00:06:53.417541 | 
2025-10-24 00:06:53.417668 | PLAY [all:!appliance*]
2025-10-24 00:06:53.465449 | 
2025-10-24 00:06:53.465627 | TASK [include_role : start-zuul-console]
2025-10-24 00:06:53.486244 | controller | ok
2025-10-24 00:06:53.514224 | 
2025-10-24 00:06:53.514371 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-24 00:06:53.921176 | controller | ok
2025-10-24 00:06:53.933447 | 
2025-10-24 00:06:53.933585 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-24 00:06:54.810911 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-24 00:06:54.820580 | 
2025-10-24 00:06:54.820649 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-24 00:06:55.359698 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.367080 | 
2025-10-24 00:06:55.367154 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-24 00:06:55.421838 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.432928 | 
2025-10-24 00:06:55.433051 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-24 00:06:55.471806 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.478816 | 
2025-10-24 00:06:55.478900 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-24 00:06:55.503277 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.510405 | 
2025-10-24 00:06:55.510473 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-24 00:06:55.555139 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.562115 | 
2025-10-24 00:06:55.562191 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-24 00:06:55.588317 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.601488 | 
2025-10-24 00:06:55.601566 | TASK [Disable Fedora Modular]
2025-10-24 00:06:55.866936 | controller | changed
2025-10-24 00:06:55.877860 | 
2025-10-24 00:06:55.878125 | TASK [Enable EPEL]
2025-10-24 00:06:55.913313 | controller | skipping: Conditional result was False
2025-10-24 00:06:55.922288 | 
2025-10-24 00:06:55.922387 | TASK [Register the RHEL node]
2025-10-24 00:06:56.526751 | 
2025-10-24 00:06:56.526941 | TASK [Show the subscription-manager status]
2025-10-24 00:06:57.094333 | controller | skipping: Conditional result was False
2025-10-24 00:06:57.100864 | 
2025-10-24 00:06:57.100937 | TASK [Enable EPEL on RHEL]
2025-10-24 00:06:57.633926 | controller | skipping: Conditional result was False
2025-10-24 00:06:57.661506 | 
2025-10-24 00:06:57.661709 | TASK [Install git and tox]
2025-10-24 00:08:28.562929 | controller | changed
2025-10-24 00:08:28.579678 | 
2025-10-24 00:08:28.579804 | TASK [include_role : prepare-workspace]
2025-10-24 00:08:28.615244 | controller | ok
2025-10-24 00:08:28.645632 | 
2025-10-24 00:08:28.645993 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-24 00:08:28.887861 | controller | ok
2025-10-24 00:08:28.899895 | 
2025-10-24 00:08:28.900006 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-24 00:14:31.368780 | controller | Output suppressed because no_log was given
2025-10-24 00:14:31.395175 | 
2025-10-24 00:14:31.395301 | TASK [include_role : prepare-workspace-openshift]
2025-10-24 00:14:31.410838 | controller | skipping: Conditional result was False
2025-10-24 00:14:31.437001 | 
2025-10-24 00:14:31.437147 | PLAY [all:!appliance]
2025-10-24 00:14:31.453970 | 
2025-10-24 00:14:31.454124 | TASK [Run add-build-sshkey role (RSA)]
2025-10-24 00:14:31.474584 | controller | ok
2025-10-24 00:14:31.491658 | 
2025-10-24 00:14:31.491780 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-24 00:14:31.741828 | controller -> localhost | ok
2025-10-24 00:14:31.758579 | 
2025-10-24 00:14:31.758765 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-24 00:14:31.788606 | controller | ok
2025-10-24 00:14:31.819151 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-24 00:14:31.829172 | 
2025-10-24 00:14:31.829311 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-24 00:14:32.408306 | controller -> localhost | Generating public/private rsa key pair.
2025-10-24 00:14:32.408482 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_rsa.
2025-10-24 00:14:32.408510 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_rsa.pub.
2025-10-24 00:14:32.408530 | controller -> localhost | The key fingerprint is:
2025-10-24 00:14:32.408549 | controller -> localhost | SHA256:8WM9E7kL7Anv2YK6V6yCldR85hvGwHdsLluyWPGmhqg zuul-build-sshkey
2025-10-24 00:14:32.408567 | controller -> localhost | The key's randomart image is:
2025-10-24 00:14:32.408585 | controller -> localhost | +---[RSA 2048]----+
2025-10-24 00:14:32.408602 | controller -> localhost | |                 |
2025-10-24 00:14:32.408620 | controller -> localhost | |             .   |
2025-10-24 00:14:32.408637 | controller -> localhost | |       +.  .o    |
2025-10-24 00:14:32.408654 | controller -> localhost | |      . =+=.+o   |
2025-10-24 00:14:32.408670 | controller -> localhost | |     . .SO**=    |
2025-10-24 00:14:32.408696 | controller -> localhost | |      o  =@+=+   |
2025-10-24 00:14:32.408719 | controller -> localhost | |     o . O+@.    |
2025-10-24 00:14:32.408737 | controller -> localhost | |    . o *.Bo     |
2025-10-24 00:14:32.408755 | controller -> localhost | |    E.o= .o..    |
2025-10-24 00:14:32.408774 | controller -> localhost | +----[SHA256]-----+
2025-10-24 00:14:32.408834 | controller -> localhost | ok: Runtime: 0:00:00.181980
2025-10-24 00:14:32.415809 | 
2025-10-24 00:14:32.415883 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-24 00:14:32.435567 | controller | ok
2025-10-24 00:14:32.446915 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-24 00:14:32.456926 | 
2025-10-24 00:14:32.457074 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-24 00:14:32.481683 | controller | skipping: Conditional result was False
2025-10-24 00:14:32.489212 | 
2025-10-24 00:14:32.489325 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-24 00:14:33.173646 | controller | changed
2025-10-24 00:14:33.179645 | 
2025-10-24 00:14:33.179719 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-24 00:14:33.434868 | controller | ok
2025-10-24 00:14:33.441165 | 
2025-10-24 00:14:33.441277 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-24 00:14:34.087808 | controller | changed
2025-10-24 00:14:34.097082 | 
2025-10-24 00:14:34.097185 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-24 00:14:34.752190 | controller | changed
2025-10-24 00:14:34.758877 | 
2025-10-24 00:14:34.758944 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-24 00:14:34.783780 | controller | skipping: Conditional result was False
2025-10-24 00:14:34.794454 | 
2025-10-24 00:14:34.794598 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-24 00:14:35.211954 | controller -> localhost | changed
2025-10-24 00:14:35.233259 | 
2025-10-24 00:14:35.233440 | TASK [add-build-sshkey : Add back temp key]
2025-10-24 00:14:35.524879 | controller -> localhost | Identity added: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_rsa (zuul-build-sshkey)
2025-10-24 00:14:35.525179 | controller -> localhost | ok: Runtime: 0:00:00.009210
2025-10-24 00:14:35.536784 | 
2025-10-24 00:14:35.536903 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-24 00:14:35.926449 | controller | ok
2025-10-24 00:14:35.932252 | 
2025-10-24 00:14:35.932349 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-24 00:14:35.971058 | controller | skipping: Conditional result was False
2025-10-24 00:14:35.990054 | 
2025-10-24 00:14:35.990214 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-24 00:14:36.022984 | controller | ok
2025-10-24 00:14:36.042276 | 
2025-10-24 00:14:36.042408 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-24 00:14:36.283782 | controller -> localhost | ok
2025-10-24 00:14:36.290991 | 
2025-10-24 00:14:36.291100 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-24 00:14:36.322277 | controller | ok
2025-10-24 00:14:36.333858 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-24 00:14:36.340135 | 
2025-10-24 00:14:36.340205 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-24 00:14:36.659358 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-24 00:14:36.659617 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_ecdsa.
2025-10-24 00:14:36.659657 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_ecdsa.pub.
2025-10-24 00:14:36.659697 | controller -> localhost | The key fingerprint is:
2025-10-24 00:14:36.659726 | controller -> localhost | SHA256:CTeCnsjNLi+7IUPqahez5cBUUDk69O4ZbBxCu+/t4AI zuul-build-sshkey
2025-10-24 00:14:36.659753 | controller -> localhost | The key's randomart image is:
2025-10-24 00:14:36.659779 | controller -> localhost | +---[ECDSA 521]---+
2025-10-24 00:14:36.659805 | controller -> localhost | |   .o..          |
2025-10-24 00:14:36.659830 | controller -> localhost | |   o =           |
2025-10-24 00:14:36.659856 | controller -> localhost | |  o * + o        |
2025-10-24 00:14:36.659882 | controller -> localhost | | . @ + + o       |
2025-10-24 00:14:36.659909 | controller -> localhost | | .= % . S        |
2025-10-24 00:14:36.659935 | controller -> localhost | |oE B B           |
2025-10-24 00:14:36.659962 | controller -> localhost | |+ + %.o          |
2025-10-24 00:14:36.659988 | controller -> localhost | |.+.B.=o          |
2025-10-24 00:14:36.660039 | controller -> localhost | |+.+++o.o         |
2025-10-24 00:14:36.660077 | controller -> localhost | +----[SHA256]-----+
2025-10-24 00:14:36.660145 | controller -> localhost | ok: Runtime: 0:00:00.008210
2025-10-24 00:14:36.670101 | 
2025-10-24 00:14:36.670235 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-24 00:14:36.703133 | controller | ok
2025-10-24 00:14:36.713645 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-24 00:14:36.726415 | 
2025-10-24 00:14:36.726543 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-24 00:14:36.751980 | controller | skipping: Conditional result was False
2025-10-24 00:14:36.760893 | 
2025-10-24 00:14:36.761083 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-24 00:14:37.101050 | controller | changed
2025-10-24 00:14:37.116485 | 
2025-10-24 00:14:37.116632 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-24 00:14:37.354950 | controller | ok
2025-10-24 00:14:37.367281 | 
2025-10-24 00:14:37.368210 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-24 00:14:38.059763 | controller | changed
2025-10-24 00:14:38.066561 | 
2025-10-24 00:14:38.066630 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-24 00:14:38.726900 | controller | changed
2025-10-24 00:14:38.737594 | 
2025-10-24 00:14:38.737679 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-24 00:14:38.768333 | controller | skipping: Conditional result was False
2025-10-24 00:14:38.776391 | 
2025-10-24 00:14:38.776488 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-24 00:14:39.026542 | controller -> localhost | changed
2025-10-24 00:14:39.043981 | 
2025-10-24 00:14:39.044145 | TASK [add-build-sshkey : Add back temp key]
2025-10-24 00:14:39.354216 | controller -> localhost | Identity added: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/dc27d2e9a6e741ada6a880d758b638f9_id_ecdsa (zuul-build-sshkey)
2025-10-24 00:14:39.354397 | controller -> localhost | ok: Runtime: 0:00:00.013790
2025-10-24 00:14:39.361219 | 
2025-10-24 00:14:39.361324 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-24 00:14:39.566847 | controller | ok
2025-10-24 00:14:39.576235 | 
2025-10-24 00:14:39.576403 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-24 00:14:39.649391 | controller | skipping: Conditional result was False
2025-10-24 00:14:39.673769 | 
2025-10-24 00:14:39.673873 | TASK [include_role : remove-zuul-sshkey]
2025-10-24 00:14:39.698889 | controller | skipping: Conditional result was False
2025-10-24 00:14:39.715679 | 
2025-10-24 00:14:39.715810 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-24 00:14:39.974051 | controller | ok: "logs"
2025-10-24 00:14:39.974302 | controller | ok: All items complete
2025-10-24 00:14:39.974341 | 
2025-10-24 00:14:40.181194 | controller | ok: "artifacts"
2025-10-24 00:14:40.392321 | controller | ok: "docs"
2025-10-24 00:14:40.409634 | 
2025-10-24 00:14:40.409752 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-24 00:14:40.675980 | controller | changed: "logs"
2025-10-24 00:14:40.896354 | controller | changed: "artifacts"
2025-10-24 00:14:41.124535 | controller | changed: "docs"
2025-10-24 00:14:41.179265 | 
2025-10-24 00:14:41.179432 | PLAY RECAP
2025-10-24 00:14:41.179494 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-24 00:14:41.179531 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-24 00:14:41.179555 | 
2025-10-24 00:14:41.320698 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-24 00:14:41.321658 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-24 00:14:41.943945 | 
2025-10-24 00:14:41.944094 | PLAY [all]
2025-10-24 00:14:41.968977 | 
2025-10-24 00:14:41.969123 | TASK [Install binary dependencies]
2025-10-24 00:14:42.019976 | controller | ok
2025-10-24 00:14:42.043643 | 
2025-10-24 00:14:42.043805 | TASK [bindep : Include find tasks]
2025-10-24 00:14:42.075823 | controller | ok
2025-10-24 00:14:42.085279 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-24 00:14:42.092323 | 
2025-10-24 00:14:42.092411 | TASK [bindep : Look for bindep.txt]
2025-10-24 00:14:42.671702 | controller | ok
2025-10-24 00:14:42.685182 | 
2025-10-24 00:14:42.685335 | TASK [bindep : Define bindep_file fact]
2025-10-24 00:14:42.712908 | controller | skipping: Conditional result was False
2025-10-24 00:14:42.729272 | 
2025-10-24 00:14:42.729479 | TASK [bindep : Look for other-requirements.txt]
2025-10-24 00:14:42.960787 | controller | ok
2025-10-24 00:14:42.972497 | 
2025-10-24 00:14:42.972690 | TASK [bindep : Define bindep_file fact]
2025-10-24 00:14:43.008646 | controller | skipping: Conditional result was False
2025-10-24 00:14:43.018779 | 
2025-10-24 00:14:43.018934 | TASK [bindep : Look for bindep fallback file]
2025-10-24 00:14:43.054288 | controller | skipping: Conditional result was False
2025-10-24 00:14:43.062146 | 
2025-10-24 00:14:43.062244 | TASK [bindep : Define bindep_file fact]
2025-10-24 00:14:43.085930 | controller | skipping: Conditional result was False
2025-10-24 00:14:43.092590 | 
2025-10-24 00:14:43.092708 | TASK [bindep : Include bindep tasks]
2025-10-24 00:14:43.116993 | controller | skipping: Conditional result was False
2025-10-24 00:14:43.123741 | 
2025-10-24 00:14:43.123844 | TASK [bindep : Include install tasks]
2025-10-24 00:14:43.148048 | controller | skipping: Conditional result was False
2025-10-24 00:14:43.155695 | 
2025-10-24 00:14:43.155822 | LOOP [bindep : Include package tasks]
2025-10-24 00:14:43.212601 | 
2025-10-24 00:14:43.212772 | TASK [Run test-setup role]
2025-10-24 00:14:43.234341 | controller | ok
2025-10-24 00:14:43.257437 | 
2025-10-24 00:14:43.257593 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-24 00:14:43.505405 | controller | ok
2025-10-24 00:14:43.511961 | 
2025-10-24 00:14:43.512067 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-24 00:14:44.044846 | controller | skipping: Conditional result was False
2025-10-24 00:14:44.078444 | 
2025-10-24 00:14:44.078555 | PLAY RECAP
2025-10-24 00:14:44.078598 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-24 00:14:44.078619 | 
2025-10-24 00:14:44.202370 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-24 00:14:44.203519 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-24 00:14:44.903531 | 
2025-10-24 00:14:44.903684 | PLAY [controller]
2025-10-24 00:14:44.926685 | 
2025-10-24 00:14:44.926831 | TASK [Create the /root directory]
2025-10-24 00:14:45.509089 | controller | ok
2025-10-24 00:14:45.522652 | 
2025-10-24 00:14:45.522808 | TASK [Install glibc-langpack-en]
2025-10-24 00:14:49.540999 | controller | ok: Nothing to do
2025-10-24 00:14:49.555460 | 
2025-10-24 00:14:49.555611 | TASK [Ensure controller directory exists]
2025-10-24 00:14:49.776557 | controller | changed
2025-10-24 00:14:49.783064 | 
2025-10-24 00:14:49.783146 | TASK [Install container runtime]
2025-10-24 00:14:49.850961 | controller | ok
2025-10-24 00:14:49.896067 | 
2025-10-24 00:14:49.896197 | LOOP [ensure-podman : Find distribution installation]
2025-10-24 00:14:49.936370 | controller | ok: "/var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-24 00:14:49.952370 | controller | included: /var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-24 00:14:49.965235 | 
2025-10-24 00:14:49.965359 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-24 00:15:57.259010 | controller | changed
2025-10-24 00:15:57.269256 | 
2025-10-24 00:15:57.269391 | TASK [ensure-podman : Fetch podman version]
2025-10-24 00:15:57.808776 | controller | Client:       Podman Engine
2025-10-24 00:15:57.808982 | controller | Version:      4.6.2
2025-10-24 00:15:57.809074 | controller | API Version:  4.6.2
2025-10-24 00:15:57.809147 | controller | Go Version:   go1.19.12
2025-10-24 00:15:57.809244 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-24 00:15:57.809318 | controller | OS/Arch:      linux/amd64
2025-10-24 00:15:58.317708 | controller | ok: Runtime: 0:00:00.181720
2025-10-24 00:15:58.327889 | 
2025-10-24 00:15:58.328172 | TASK [ensure-podman : Print podman version installed]
2025-10-24 00:15:58.375749 | Podman version: Client:       Podman Engine
2025-10-24 00:15:58.376066 | Version:      4.6.2
2025-10-24 00:15:58.376139 | API Version:  4.6.2
2025-10-24 00:15:58.376186 | Go Version:   go1.19.12
2025-10-24 00:15:58.376228 | Built:        Mon Aug 28 19:38:31 2023
2025-10-24 00:15:58.376271 | OS/Arch:      linux/amd64
2025-10-24 00:15:58.389215 | 
2025-10-24 00:15:58.389385 | TASK [ensure-podman : Validate podman engine]
2025-10-24 00:15:58.936543 | controller | skipping: Conditional result was False
2025-10-24 00:15:58.950894 | 
2025-10-24 00:15:58.951114 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-24 00:15:58.967373 | controller | skipping: Conditional result was False
2025-10-24 00:15:58.979423 | 
2025-10-24 00:15:58.979515 | TASK [Ensure python3.8 is present]
2025-10-24 00:15:58.993193 | controller | skipping: Conditional result was False
2025-10-24 00:15:59.000336 | 
2025-10-24 00:15:59.000435 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-24 00:15:59.019100 | controller | ok
2025-10-24 00:15:59.041407 | 
2025-10-24 00:15:59.041562 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-24 00:16:00.523644 | controller | ok: Nothing to do
2025-10-24 00:16:00.529443 | 
2025-10-24 00:16:00.529525 | TASK [our-ensure-python : Also install python3-devel]
2025-10-24 00:16:09.205583 | controller | changed
2025-10-24 00:16:09.223852 | 
2025-10-24 00:16:09.223982 | TASK [Run ensure-virtualenv role]
2025-10-24 00:16:09.263188 | controller | ok
2025-10-24 00:16:09.314661 | 
2025-10-24 00:16:09.314815 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-24 00:16:09.564846 | controller | /usr/bin/virtualenv
2025-10-24 00:16:09.874409 | controller | ok: Runtime: 0:00:00.005139
2025-10-24 00:16:09.890123 | 
2025-10-24 00:16:09.890311 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-24 00:16:09.913000 | controller | skipping: Conditional result was False
2025-10-24 00:16:09.913557 | controller | ok: All items complete
2025-10-24 00:16:09.913627 | 
2025-10-24 00:16:09.976256 | 
2025-10-24 00:16:09.976404 | TASK [Find the full path of the Python interpreter]
2025-10-24 00:16:10.209687 | controller | /usr/bin/python3
2025-10-24 00:16:10.508872 | controller | ok
2025-10-24 00:16:10.526804 | 
2025-10-24 00:16:10.527070 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-24 00:16:11.386327 | controller | created virtual environment CPython3.11.0.final.0-64 in 482ms
2025-10-24 00:16:11.407078 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-24 00:16:11.407114 | 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-24 00:16:11.407124 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-24 00:16:11.407147 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-24 00:16:11.579847 | controller | changed
2025-10-24 00:16:11.594913 | 
2025-10-24 00:16:11.595122 | TASK [Set selinux package]
2025-10-24 00:16:11.625651 | controller | ok
2025-10-24 00:16:11.639081 | 
2025-10-24 00:16:11.639289 | TASK [Set selinux package (Fedora)]
2025-10-24 00:16:11.695803 | controller | ok
2025-10-24 00:16:11.704994 | 
2025-10-24 00:16:11.705142 | TASK [Install selinux into virtualenv]
2025-10-24 00:16:49.162900 | controller | Collecting selinux-please-lie-to-me
2025-10-24 00:17:01.420832 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-24 00:17:01.755562 | controller | Collecting setuptools<50.0.0
2025-10-24 00:17:01.759649 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-24 00:17:01.805164 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.4 MB/s eta 0:00:00
2025-10-24 00:17:01.889949 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-24 00:17:01.891666 | controller |   Attempting uninstall: setuptools
2025-10-24 00:17:01.891714 | controller |     Found existing installation: setuptools 62.6.0
2025-10-24 00:17:01.950846 | controller |     Uninstalling setuptools-62.6.0:
2025-10-24 00:17:01.960007 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-24 00:17:02.301995 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-24 00:17:13.801011 | controller |
2025-10-24 00:17:13.909996 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-24 00:17:13.910132 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-24 00:17:14.304256 | controller | ok: Runtime: 0:01:01.971336
2025-10-24 00:17:14.317120 | 
2025-10-24 00:17:14.317241 | TASK [Install pytest-forked into virtualenv]
2025-10-24 00:17:26.056306 | controller | Collecting pytest-forked
2025-10-24 00:17:38.286859 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-24 00:17:38.331605 | controller | Collecting py
2025-10-24 00:17:38.336460 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-24 00:17:38.366818 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.7 MB/s eta 0:00:00
2025-10-24 00:17:38.480129 | controller | Collecting pytest>=3.10
2025-10-24 00:17:38.485532 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-24 00:17:38.499256 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 31.5 MB/s eta 0:00:00
2025-10-24 00:17:38.531407 | controller | Collecting iniconfig>=1
2025-10-24 00:17:38.535508 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-24 00:17:38.574230 | controller | Collecting packaging>=20
2025-10-24 00:17:38.577393 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-24 00:17:38.584396 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.1 MB/s eta 0:00:00
2025-10-24 00:17:38.610511 | controller | Collecting pluggy<2,>=1.5
2025-10-24 00:17:38.615394 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-24 00:17:38.662593 | controller | Collecting pygments>=2.7.2
2025-10-24 00:17:38.665997 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-24 00:17:38.698724 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 39.8 MB/s eta 0:00:00
2025-10-24 00:17:38.765926 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-24 00:17:39.852490 | controller | Successfully installed iniconfig-2.3.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-24 00:17:39.861005 | controller |
2025-10-24 00:17:39.928943 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-24 00:17:39.928980 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-24 00:17:40.371947 | controller | ok: Runtime: 0:00:25.379372
2025-10-24 00:17:40.387336 | 
2025-10-24 00:17:40.387511 | TASK [Update pip]
2025-10-24 00:17:40.957302 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-24 00:17:51.367007 | controller | Collecting pip
2025-10-24 00:18:03.561974 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-24 00:18:03.629802 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 27.7 MB/s eta 0:00:00
2025-10-24 00:18:03.694103 | controller | Installing collected packages: pip
2025-10-24 00:18:03.694210 | controller |   Attempting uninstall: pip
2025-10-24 00:18:03.696317 | controller |     Found existing installation: pip 22.2.2
2025-10-24 00:18:03.836159 | controller |     Uninstalling pip-22.2.2:
2025-10-24 00:18:03.850987 | controller |       Successfully uninstalled pip-22.2.2
2025-10-24 00:18:04.653753 | controller | Successfully installed pip-25.2
2025-10-24 00:18:04.956189 | controller | ok: Runtime: 0:00:24.100828
2025-10-24 00:18:04.965849 | 
2025-10-24 00:18:04.966313 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-24 00:18:05.162383 | controller | changed
2025-10-24 00:18:05.168674 | 
2025-10-24 00:18:05.168791 | TASK [Install ansible into virtualenv]
2025-10-24 00:18:05.679630 | controller | Processing ./src/github.com/ansible/ansible
2025-10-24 00:18:05.682864 | controller |   Installing build dependencies: started
2025-10-24 00:18:40.695709 | controller |   Installing build dependencies: finished with status 'done'
2025-10-24 00:18:40.696321 | controller |   Getting requirements to build wheel: started
2025-10-24 00:18:41.423323 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-24 00:18:41.424603 | controller |   Preparing metadata (pyproject.toml): started
2025-10-24 00:18:41.883483 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-24 00:18:41.888737 | 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-24 00:18:41.893320 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-24 00:18:42.224372 | controller | ERROR
2025-10-24 00:18:42.224592 | controller | {
2025-10-24 00:18:42.224652 | controller |   "delta": "0:00:36.595148",
2025-10-24 00:18:42.224696 | controller |   "end": "2025-10-24 00:18:41.969420",
2025-10-24 00:18:42.224735 | controller |   "msg": "non-zero return code",
2025-10-24 00:18:42.224789 | controller |   "rc": 1,
2025-10-24 00:18:42.224826 | controller |   "start": "2025-10-24 00:18:05.374272"
2025-10-24 00:18:42.224862 | controller | }
failure
2025-10-24 00:18:42.227655 | 
2025-10-24 00:18:42.227933 | PLAY RECAP
2025-10-24 00:18:42.228291 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-24 00:18:42.228364 | 
2025-10-24 00:18:42.370765 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-24 00:18:42.372832 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-24 00:18:42.992232 | 
2025-10-24 00:18:42.992352 | PLAY [all]
2025-10-24 00:18:43.013724 | 
2025-10-24 00:18:43.013845 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-24 00:18:43.467152 | controller | changed: non-zero return code
2025-10-24 00:18:43.476690 | 
2025-10-24 00:18:43.476865 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-24 00:18:43.502544 | controller | skipping: Conditional result was False
2025-10-24 00:18:43.512467 | 
2025-10-24 00:18:43.512613 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-24 00:18:43.547708 | 
2025-10-24 00:18:43.547925 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-24 00:18:43.582436 | 
2025-10-24 00:18:43.582710 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-24 00:18:43.599394 | controller | skipping: Conditional result was False
2025-10-24 00:18:43.607652 | 
2025-10-24 00:18:43.607768 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-24 00:18:43.640984 | 
2025-10-24 00:18:43.641162 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-24 00:18:43.655809 | controller | skipping: Conditional result was False
2025-10-24 00:18:43.665690 | 
2025-10-24 00:18:43.665797 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-24 00:18:43.681344 | controller | skipping: Conditional result was False
2025-10-24 00:18:43.692836 | 
2025-10-24 00:18:43.692981 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-24 00:18:43.708380 | controller | skipping: Conditional result was False
2025-10-24 00:18:43.754261 | 
2025-10-24 00:18:43.754370 | PLAY RECAP
2025-10-24 00:18:43.754428 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-24 00:18:43.754458 | 
2025-10-24 00:18:43.854112 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-24 00:18:43.854950 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-24 00:18:44.510888 | 
2025-10-24 00:18:44.511147 | PLAY [all:!appliance*]
2025-10-24 00:18:44.539788 | 
2025-10-24 00:18:44.539926 | TASK [unregister the node]
2025-10-24 00:18:45.071784 | controller | skipping: Conditional result was False
2025-10-24 00:18:45.084952 | 
2025-10-24 00:18:45.085188 | TASK [include_role : fetch-output]
2025-10-24 00:18:45.124307 | controller | ok
2025-10-24 00:18:45.167527 | 
2025-10-24 00:18:45.167685 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-24 00:18:45.244568 | controller | skipping: Conditional result was False
2025-10-24 00:18:45.267805 | 
2025-10-24 00:18:45.267979 | TASK [fetch-output : Set log path for single node]
2025-10-24 00:18:45.323796 | controller | ok
2025-10-24 00:18:45.332000 | 
2025-10-24 00:18:45.332123 | LOOP [fetch-output : Ensure local output dirs]
2025-10-24 00:18:45.780206 | controller -> localhost | ok: "/var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/logs"
2025-10-24 00:18:46.028562 | controller -> localhost | changed: "/var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/artifacts"
2025-10-24 00:18:46.305821 | controller -> localhost | changed: "/var/lib/zuul/builds/dc27d2e9a6e741ada6a880d758b638f9/work/docs"
2025-10-24 00:18:46.318499 | 
2025-10-24 00:18:46.318641 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-24 00:18:47.104820 | controller | changed:
2025-10-24 00:18:47.110698 | controller | .d..t...... ./
2025-10-24 00:18:47.110767 | controller | cd+++++++++ controller/
2025-10-24 00:18:47.110819 | controller | changed: All items complete
2025-10-24 00:18:47.110849 | 
2025-10-24 00:18:47.588133 | controller | changed: .d..t...... ./
2025-10-24 00:18:48.137306 | controller | changed: .d..t...... ./
2025-10-24 00:18:48.159863 | 
2025-10-24 00:18:48.160009 | TASK [include_role : fetch-output-openshift]
2025-10-24 00:18:48.175231 | controller | skipping: Conditional result was False
2025-10-24 00:18:48.184975 | 
2025-10-24 00:18:48.185146 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-24 00:18:48.212607 | controller | skipping: Conditional result was False
2025-10-24 00:18:48.222359 | controller | skipping: Conditional result was False
2025-10-24 00:18:48.269185 | 
2025-10-24 00:18:48.269288 | PLAY [localhost]
2025-10-24 00:18:48.281615 | 
2025-10-24 00:18:48.281691 | TASK [Run Zuul manifest role]
2025-10-24 00:18:48.300638 | localhost | ok
2025-10-24 00:18:48.322501 | 
2025-10-24 00:18:48.322647 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-24 00:18:48.666823 | localhost | changed
2025-10-24 00:18:48.671394 | 
2025-10-24 00:18:48.671453 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-24 00:18:48.719940 | localhost | ok
2025-10-24 00:18:48.728119 | 
2025-10-24 00:18:48.728187 | TASK [Set zuul-log-path fact]
2025-10-24 00:18:48.746099 | localhost | ok
2025-10-24 00:18:48.761454 | 
2025-10-24 00:18:48.761531 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-24 00:18:48.789740 | localhost | ok
2025-10-24 00:18:48.797566 | 
2025-10-24 00:18:48.797627 | LOOP [Run upload-logs-swift role]
2025-10-24 00:18:48.833652 | localhost | Output suppressed because no_log was given
2025-10-24 00:18:48.860758 | 
2025-10-24 00:18:48.860857 | TASK [Set zuul-log-path fact]
2025-10-24 00:18:48.884846 | localhost | skipping: Conditional result was False
2025-10-24 00:18:48.891235 | 
2025-10-24 00:18:48.891317 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-24 00:18:49.290259 | localhost -> localhost | ok: Runtime: 0:00:00.005203
2025-10-24 00:18:49.339457 | 
2025-10-24 00:18:49.339574 | TASK [upload-logs-swift : Upload logs to swift]