2025-11-25 00:06:52.118461 | Job console starting...
2025-11-25 00:06:52.133259 | Updating repositories
2025-11-25 00:06:52.347358 | Preparing job workspace
2025-11-25 00:06:58.729606 | Running Ansible setup...
2025-11-25 00:07:03.937916 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-25 00:07:04.603977 | 
2025-11-25 00:07:04.604098 | PLAY [localhost]
2025-11-25 00:07:04.612596 | 
2025-11-25 00:07:04.612675 | TASK [Gathering Facts]
2025-11-25 00:07:05.587104 | localhost | ok
2025-11-25 00:07:05.601323 | 
2025-11-25 00:07:05.601432 | TASK [Setup log path fact]
2025-11-25 00:07:05.619491 | localhost | ok
2025-11-25 00:07:05.632659 | 
2025-11-25 00:07:05.632795 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-25 00:07:05.671665 | localhost | ok
2025-11-25 00:07:05.680213 | 
2025-11-25 00:07:05.680325 | TASK [emit-job-header : Print job information]
2025-11-25 00:07:05.729256 | # Job Information
2025-11-25 00:07:05.729414 | Ansible Version: 2.15.12
2025-11-25 00:07:05.729447 | Job: ansible-test-sanity-docker-devel
2025-11-25 00:07:05.729470 | Pipeline: periodic
2025-11-25 00:07:05.729491 | Executor: ze03.softwarefactory-project.io
2025-11-25 00:07:05.729510 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-25 00:07:05.729534 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/53f/ansible/53f39a5c011e494c98a2da3d3dbfc401/
2025-11-25 00:07:05.729555 | Event ID: 79272cc69eda4d18bcd9786106633695
2025-11-25 00:07:05.733685 | 
2025-11-25 00:07:05.733795 | LOOP [emit-job-header : Print node information]
2025-11-25 00:07:05.857521 | localhost | ok:
2025-11-25 00:07:05.857798 | localhost | # Node Information
2025-11-25 00:07:05.857841 | localhost | Inventory Hostname: controller
2025-11-25 00:07:05.857871 | localhost | Hostname: np0005534275
2025-11-25 00:07:05.857899 | localhost | Username: zuul
2025-11-25 00:07:05.857928 | localhost | Distro: Fedora 37
2025-11-25 00:07:05.857955 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-25 00:07:05.857980 | localhost | Region: ca-ymq-1
2025-11-25 00:07:05.858005 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-25 00:07:05.858029 | localhost | Product Name: OpenStack Nova
2025-11-25 00:07:05.858054 | localhost | Interface IP: 162.253.55.84
2025-11-25 00:07:05.871954 | 
2025-11-25 00:07:05.872087 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-25 00:07:06.271612 | localhost -> localhost | changed
2025-11-25 00:07:06.279258 | 
2025-11-25 00:07:06.279351 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-25 00:07:08.142254 | localhost -> localhost | changed
2025-11-25 00:07:08.165135 | 
2025-11-25 00:07:08.165244 | PLAY [all:!appliance*]
2025-11-25 00:07:08.183857 | 
2025-11-25 00:07:08.184000 | TASK [include_role : start-zuul-console]
2025-11-25 00:07:08.221037 | controller | ok
2025-11-25 00:07:08.241872 | 
2025-11-25 00:07:08.242053 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-25 00:07:08.652145 | controller | ok
2025-11-25 00:07:08.674607 | 
2025-11-25 00:07:08.674755 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-25 00:07:10.322641 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-25 00:07:10.329981 | 
2025-11-25 00:07:10.330070 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-25 00:07:10.863535 | controller | skipping: Conditional result was False
2025-11-25 00:07:10.881963 | 
2025-11-25 00:07:10.882203 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-25 00:07:10.910754 | controller | skipping: Conditional result was False
2025-11-25 00:07:10.920054 | 
2025-11-25 00:07:10.920149 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-25 00:07:10.945791 | controller | skipping: Conditional result was False
2025-11-25 00:07:10.952101 | 
2025-11-25 00:07:10.952173 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-25 00:07:10.980087 | controller | skipping: Conditional result was False
2025-11-25 00:07:10.991384 | 
2025-11-25 00:07:10.991514 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-25 00:07:11.016880 | controller | skipping: Conditional result was False
2025-11-25 00:07:11.026502 | 
2025-11-25 00:07:11.026671 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-25 00:07:11.052144 | controller | skipping: Conditional result was False
2025-11-25 00:07:11.068434 | 
2025-11-25 00:07:11.068519 | TASK [Disable Fedora Modular]
2025-11-25 00:07:11.301184 | controller | changed
2025-11-25 00:07:11.315174 | 
2025-11-25 00:07:11.315324 | TASK [Enable EPEL]
2025-11-25 00:07:11.342907 | controller | skipping: Conditional result was False
2025-11-25 00:07:11.359428 | 
2025-11-25 00:07:11.359594 | TASK [Register the RHEL node]
2025-11-25 00:07:11.917566 | 
2025-11-25 00:07:11.917832 | TASK [Show the subscription-manager status]
2025-11-25 00:07:12.543246 | controller | skipping: Conditional result was False
2025-11-25 00:07:12.552201 | 
2025-11-25 00:07:12.552290 | TASK [Enable EPEL on RHEL]
2025-11-25 00:07:13.095071 | controller | skipping: Conditional result was False
2025-11-25 00:07:13.109643 | 
2025-11-25 00:07:13.109837 | TASK [Install git and tox]
2025-11-25 00:08:51.847115 | controller | changed
2025-11-25 00:08:51.855592 | 
2025-11-25 00:08:51.855665 | TASK [include_role : prepare-workspace]
2025-11-25 00:08:51.875662 | controller | ok
2025-11-25 00:08:51.897460 | 
2025-11-25 00:08:51.897555 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-25 00:08:52.153319 | controller | ok
2025-11-25 00:08:52.168679 | 
2025-11-25 00:08:52.168861 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-25 00:09:12.063011 | controller | Output suppressed because no_log was given
2025-11-25 00:09:12.077441 | 
2025-11-25 00:09:12.077515 | TASK [include_role : prepare-workspace-openshift]
2025-11-25 00:09:12.094031 | controller | skipping: Conditional result was False
2025-11-25 00:09:12.117001 | 
2025-11-25 00:09:12.117083 | PLAY [all:!appliance]
2025-11-25 00:09:12.133692 | 
2025-11-25 00:09:12.133821 | TASK [Run add-build-sshkey role (RSA)]
2025-11-25 00:09:12.163078 | controller | ok
2025-11-25 00:09:12.177330 | 
2025-11-25 00:09:12.177401 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-25 00:09:12.476215 | controller -> localhost | ok
2025-11-25 00:09:12.482787 | 
2025-11-25 00:09:12.482851 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-25 00:09:12.512544 | controller | ok
2025-11-25 00:09:12.532187 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-25 00:09:12.538133 | 
2025-11-25 00:09:12.538192 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-25 00:09:13.103176 | controller -> localhost | Generating public/private rsa key pair.
2025-11-25 00:09:13.103463 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_rsa.
2025-11-25 00:09:13.103505 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_rsa.pub.
2025-11-25 00:09:13.103535 | controller -> localhost | The key fingerprint is:
2025-11-25 00:09:13.103562 | controller -> localhost | SHA256:+cCvK3V9K1gfZ9fvhaUclsvRfoao0/ByWv6JvUcNuLA zuul-build-sshkey
2025-11-25 00:09:13.103589 | controller -> localhost | The key's randomart image is:
2025-11-25 00:09:13.103615 | controller -> localhost | +---[RSA 2048]----+
2025-11-25 00:09:13.103640 | controller -> localhost | |                 |
2025-11-25 00:09:13.103666 | controller -> localhost | |                 |
2025-11-25 00:09:13.103691 | controller -> localhost | |             .   |
2025-11-25 00:09:13.103714 | controller -> localhost | |       . .. . .o |
2025-11-25 00:09:13.103765 | controller -> localhost | |        S  + .=.=|
2025-11-25 00:09:13.103804 | controller -> localhost | |        .+E +=oXB|
2025-11-25 00:09:13.103836 | controller -> localhost | |       . .o*ooB*B|
2025-11-25 00:09:13.103862 | controller -> localhost | |      .  .++=ooo=|
2025-11-25 00:09:13.103887 | controller -> localhost | |       .o.o=oo=+.|
2025-11-25 00:09:13.103920 | controller -> localhost | +----[SHA256]-----+
2025-11-25 00:09:13.103993 | controller -> localhost | ok: Runtime: 0:00:00.142737
2025-11-25 00:09:13.114774 | 
2025-11-25 00:09:13.114893 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-25 00:09:13.149377 | controller | ok
2025-11-25 00:09:13.165521 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-25 00:09:13.181097 | 
2025-11-25 00:09:13.181227 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-25 00:09:13.206658 | controller | skipping: Conditional result was False
2025-11-25 00:09:13.217352 | 
2025-11-25 00:09:13.217477 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-25 00:09:13.715146 | controller | changed
2025-11-25 00:09:13.724920 | 
2025-11-25 00:09:13.725044 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-25 00:09:13.951063 | controller | ok
2025-11-25 00:09:13.957339 | 
2025-11-25 00:09:13.957401 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-25 00:09:14.630422 | controller | changed
2025-11-25 00:09:14.646771 | 
2025-11-25 00:09:14.646930 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-25 00:09:15.300626 | controller | changed
2025-11-25 00:09:15.307216 | 
2025-11-25 00:09:15.307299 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-25 00:09:15.332471 | controller | skipping: Conditional result was False
2025-11-25 00:09:15.343521 | 
2025-11-25 00:09:15.343658 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-25 00:09:15.807625 | controller -> localhost | changed
2025-11-25 00:09:15.820931 | 
2025-11-25 00:09:15.821044 | TASK [add-build-sshkey : Add back temp key]
2025-11-25 00:09:16.151658 | controller -> localhost | Identity added: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_rsa (zuul-build-sshkey)
2025-11-25 00:09:16.151944 | controller -> localhost | ok: Runtime: 0:00:00.013920
2025-11-25 00:09:16.160437 | 
2025-11-25 00:09:16.160522 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-25 00:09:16.522441 | controller | ok
2025-11-25 00:09:16.536501 | 
2025-11-25 00:09:16.536702 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-25 00:09:16.574769 | controller | skipping: Conditional result was False
2025-11-25 00:09:16.595193 | 
2025-11-25 00:09:16.595348 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-25 00:09:16.630697 | controller | ok
2025-11-25 00:09:16.657542 | 
2025-11-25 00:09:16.657697 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-25 00:09:16.939393 | controller -> localhost | ok
2025-11-25 00:09:16.955511 | 
2025-11-25 00:09:16.955696 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-25 00:09:16.988982 | controller | ok
2025-11-25 00:09:17.011146 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-25 00:09:17.020465 | 
2025-11-25 00:09:17.020574 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-25 00:09:17.355149 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-25 00:09:17.355620 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_ecdsa.
2025-11-25 00:09:17.355688 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_ecdsa.pub.
2025-11-25 00:09:17.355776 | controller -> localhost | The key fingerprint is:
2025-11-25 00:09:17.355829 | controller -> localhost | SHA256:nEHnQxfLxKZalW1wAdROYwgE9SrMF7rTBzUQQQKvK0I zuul-build-sshkey
2025-11-25 00:09:17.355870 | controller -> localhost | The key's randomart image is:
2025-11-25 00:09:17.355910 | controller -> localhost | +---[ECDSA 521]---+
2025-11-25 00:09:17.355948 | controller -> localhost | |      ..+=@*BOo. |
2025-11-25 00:09:17.355985 | controller -> localhost | |       o = **oB  |
2025-11-25 00:09:17.356021 | controller -> localhost | |        o ++*= . |
2025-11-25 00:09:17.356057 | controller -> localhost | |       = +o= ..  |
2025-11-25 00:09:17.356093 | controller -> localhost | |  E   . So+      |
2025-11-25 00:09:17.356129 | controller -> localhost | | .     ..= .     |
2025-11-25 00:09:17.356166 | controller -> localhost | |  . . . o . .    |
2025-11-25 00:09:17.356203 | controller -> localhost | |   . .   . .     |
2025-11-25 00:09:17.356239 | controller -> localhost | |                 |
2025-11-25 00:09:17.356276 | controller -> localhost | +----[SHA256]-----+
2025-11-25 00:09:17.356379 | controller -> localhost | ok: Runtime: 0:00:00.009704
2025-11-25 00:09:17.371486 | 
2025-11-25 00:09:17.371638 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-25 00:09:17.412516 | controller | ok
2025-11-25 00:09:17.435412 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-25 00:09:17.448853 | 
2025-11-25 00:09:17.448941 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-25 00:09:17.474283 | controller | skipping: Conditional result was False
2025-11-25 00:09:17.486674 | 
2025-11-25 00:09:17.486801 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-25 00:09:17.780681 | controller | changed
2025-11-25 00:09:17.796643 | 
2025-11-25 00:09:17.796866 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-25 00:09:18.052908 | controller | ok
2025-11-25 00:09:18.069156 | 
2025-11-25 00:09:18.069298 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-25 00:09:18.754623 | controller | changed
2025-11-25 00:09:18.768140 | 
2025-11-25 00:09:18.768281 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-25 00:09:19.421473 | controller | changed
2025-11-25 00:09:19.484770 | 
2025-11-25 00:09:19.484933 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-25 00:09:19.520154 | controller | skipping: Conditional result was False
2025-11-25 00:09:19.529349 | 
2025-11-25 00:09:19.529439 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-25 00:09:19.841146 | controller -> localhost | changed
2025-11-25 00:09:19.865975 | 
2025-11-25 00:09:19.866128 | TASK [add-build-sshkey : Add back temp key]
2025-11-25 00:09:20.198091 | controller -> localhost | Identity added: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/53f39a5c011e494c98a2da3d3dbfc401_id_ecdsa (zuul-build-sshkey)
2025-11-25 00:09:20.198324 | controller -> localhost | ok: Runtime: 0:00:00.012263
2025-11-25 00:09:20.205681 | 
2025-11-25 00:09:20.205785 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-25 00:09:20.410499 | controller | ok
2025-11-25 00:09:20.416454 | 
2025-11-25 00:09:20.416523 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-25 00:09:20.451260 | controller | skipping: Conditional result was False
2025-11-25 00:09:20.464173 | 
2025-11-25 00:09:20.464270 | TASK [include_role : remove-zuul-sshkey]
2025-11-25 00:09:20.488967 | controller | skipping: Conditional result was False
2025-11-25 00:09:20.496083 | 
2025-11-25 00:09:20.496156 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-25 00:09:20.760834 | controller | ok: "logs"
2025-11-25 00:09:20.761524 | controller | ok: All items complete
2025-11-25 00:09:20.761615 | 
2025-11-25 00:09:20.970151 | controller | ok: "artifacts"
2025-11-25 00:09:21.184075 | controller | ok: "docs"
2025-11-25 00:09:21.191402 | 
2025-11-25 00:09:21.191476 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-25 00:09:21.441407 | controller | changed: "logs"
2025-11-25 00:09:21.655074 | controller | changed: "artifacts"
2025-11-25 00:09:21.866881 | controller | changed: "docs"
2025-11-25 00:09:21.933098 | 
2025-11-25 00:09:21.933213 | PLAY RECAP
2025-11-25 00:09:21.933272 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-25 00:09:21.933307 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-25 00:09:21.933331 | 
2025-11-25 00:09:22.063419 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-25 00:09:22.064420 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-25 00:09:22.638875 | 
2025-11-25 00:09:22.638995 | PLAY [all]
2025-11-25 00:09:22.662303 | 
2025-11-25 00:09:22.662426 | TASK [Install binary dependencies]
2025-11-25 00:09:22.750124 | controller | ok
2025-11-25 00:09:22.785131 | 
2025-11-25 00:09:22.785288 | TASK [bindep : Include find tasks]
2025-11-25 00:09:22.818060 | controller | ok
2025-11-25 00:09:22.829281 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-25 00:09:22.837842 | 
2025-11-25 00:09:22.837929 | TASK [bindep : Look for bindep.txt]
2025-11-25 00:09:23.212980 | controller | ok
2025-11-25 00:09:23.225890 | 
2025-11-25 00:09:23.226237 | TASK [bindep : Define bindep_file fact]
2025-11-25 00:09:23.244100 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.258474 | 
2025-11-25 00:09:23.258691 | TASK [bindep : Look for other-requirements.txt]
2025-11-25 00:09:23.471939 | controller | ok
2025-11-25 00:09:23.485077 | 
2025-11-25 00:09:23.485302 | TASK [bindep : Define bindep_file fact]
2025-11-25 00:09:23.512612 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.526159 | 
2025-11-25 00:09:23.526337 | TASK [bindep : Look for bindep fallback file]
2025-11-25 00:09:23.563770 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.579389 | 
2025-11-25 00:09:23.579558 | TASK [bindep : Define bindep_file fact]
2025-11-25 00:09:23.607460 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.622369 | 
2025-11-25 00:09:23.622566 | TASK [bindep : Include bindep tasks]
2025-11-25 00:09:23.650372 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.664051 | 
2025-11-25 00:09:23.664236 | TASK [bindep : Include install tasks]
2025-11-25 00:09:23.690762 | controller | skipping: Conditional result was False
2025-11-25 00:09:23.700844 | 
2025-11-25 00:09:23.701017 | LOOP [bindep : Include package tasks]
2025-11-25 00:09:23.774359 | 
2025-11-25 00:09:23.774646 | TASK [Run test-setup role]
2025-11-25 00:09:23.799890 | controller | ok
2025-11-25 00:09:23.826449 | 
2025-11-25 00:09:23.826594 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-25 00:09:24.061624 | controller | ok
2025-11-25 00:09:24.077400 | 
2025-11-25 00:09:24.077606 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-25 00:09:24.631863 | controller | skipping: Conditional result was False
2025-11-25 00:09:24.686460 | 
2025-11-25 00:09:24.686572 | PLAY RECAP
2025-11-25 00:09:24.686618 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-25 00:09:24.686640 | 
2025-11-25 00:09:24.783704 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-25 00:09:24.784630 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-25 00:09:25.424543 | 
2025-11-25 00:09:25.424691 | PLAY [controller]
2025-11-25 00:09:25.445007 | 
2025-11-25 00:09:25.445099 | TASK [Create the /root directory]
2025-11-25 00:09:25.837843 | controller | ok
2025-11-25 00:09:25.851501 | 
2025-11-25 00:09:25.851700 | TASK [Install glibc-langpack-en]
2025-11-25 00:09:29.995935 | controller | ok: Nothing to do
2025-11-25 00:09:30.007552 | 
2025-11-25 00:09:30.007663 | TASK [Ensure controller directory exists]
2025-11-25 00:09:30.232934 | controller | changed
2025-11-25 00:09:30.241054 | 
2025-11-25 00:09:30.241145 | TASK [Install container runtime]
2025-11-25 00:09:30.324589 | controller | ok
2025-11-25 00:09:30.374620 | 
2025-11-25 00:09:30.374789 | LOOP [ensure-podman : Find distribution installation]
2025-11-25 00:09:30.421764 | controller | ok: "/var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-25 00:09:30.442221 | controller | included: /var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-25 00:09:30.452040 | 
2025-11-25 00:09:30.452154 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-25 00:10:39.184195 | controller | changed
2025-11-25 00:10:39.193785 | 
2025-11-25 00:10:39.193874 | TASK [ensure-podman : Fetch podman version]
2025-11-25 00:10:39.751647 | controller | Client:       Podman Engine
2025-11-25 00:10:39.751753 | controller | Version:      4.6.2
2025-11-25 00:10:39.751803 | controller | API Version:  4.6.2
2025-11-25 00:10:39.751847 | controller | Go Version:   go1.19.12
2025-11-25 00:10:39.751905 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-25 00:10:39.751949 | controller | OS/Arch:      linux/amd64
2025-11-25 00:10:40.234943 | controller | ok: Runtime: 0:00:00.199266
2025-11-25 00:10:40.244485 | 
2025-11-25 00:10:40.244634 | TASK [ensure-podman : Print podman version installed]
2025-11-25 00:10:40.288440 | Podman version: Client:       Podman Engine
2025-11-25 00:10:40.288637 | Version:      4.6.2
2025-11-25 00:10:40.288675 | API Version:  4.6.2
2025-11-25 00:10:40.288703 | Go Version:   go1.19.12
2025-11-25 00:10:40.288752 | Built:        Mon Aug 28 19:38:31 2023
2025-11-25 00:10:40.288782 | OS/Arch:      linux/amd64
2025-11-25 00:10:40.298455 | 
2025-11-25 00:10:40.298597 | TASK [ensure-podman : Validate podman engine]
2025-11-25 00:10:40.832822 | controller | skipping: Conditional result was False
2025-11-25 00:10:40.842787 | 
2025-11-25 00:10:40.842906 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-25 00:10:40.869362 | controller | skipping: Conditional result was False
2025-11-25 00:10:40.886013 | 
2025-11-25 00:10:40.886156 | TASK [Ensure python3.8 is present]
2025-11-25 00:10:40.912346 | controller | skipping: Conditional result was False
2025-11-25 00:10:40.921947 | 
2025-11-25 00:10:40.922091 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-25 00:10:40.943742 | controller | ok
2025-11-25 00:10:40.972332 | 
2025-11-25 00:10:40.972492 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-25 00:10:42.529622 | controller | ok: Nothing to do
2025-11-25 00:10:42.539390 | 
2025-11-25 00:10:42.539538 | TASK [our-ensure-python : Also install python3-devel]
2025-11-25 00:10:53.892309 | controller | changed
2025-11-25 00:10:53.917869 | 
2025-11-25 00:10:53.918043 | TASK [Run ensure-virtualenv role]
2025-11-25 00:10:53.943112 | controller | ok
2025-11-25 00:10:53.974497 | 
2025-11-25 00:10:53.974645 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-25 00:10:54.191448 | controller | /usr/bin/virtualenv
2025-11-25 00:10:54.510222 | controller | ok: Runtime: 0:00:00.003785
2025-11-25 00:10:54.525369 | 
2025-11-25 00:10:54.525555 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-25 00:10:54.549689 | controller | skipping: Conditional result was False
2025-11-25 00:10:54.550042 | controller | ok: All items complete
2025-11-25 00:10:54.550078 | 
2025-11-25 00:10:54.582333 | 
2025-11-25 00:10:54.582706 | TASK [Find the full path of the Python interpreter]
2025-11-25 00:10:54.838687 | controller | /usr/bin/python3
2025-11-25 00:10:55.156000 | controller | ok
2025-11-25 00:10:55.164500 | 
2025-11-25 00:10:55.164613 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-25 00:10:56.037675 | controller | created virtual environment CPython3.11.0.final.0-64 in 502ms
2025-11-25 00:10:56.054772 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-25 00:10:56.054821 | 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-11-25 00:10:56.054831 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-25 00:10:56.054853 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-25 00:10:56.208671 | controller | changed
2025-11-25 00:10:56.217787 | 
2025-11-25 00:10:56.217884 | TASK [Set selinux package]
2025-11-25 00:10:56.240801 | controller | ok
2025-11-25 00:10:56.248549 | 
2025-11-25 00:10:56.248637 | TASK [Set selinux package (Fedora)]
2025-11-25 00:10:56.282155 | controller | ok
2025-11-25 00:10:56.290374 | 
2025-11-25 00:10:56.290468 | TASK [Install selinux into virtualenv]
2025-11-25 00:11:09.922832 | controller | Collecting selinux-please-lie-to-me
2025-11-25 00:11:22.171161 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-25 00:11:22.463231 | controller | Collecting setuptools<50.0.0
2025-11-25 00:11:22.468117 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-25 00:11:22.503626 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 25.9 MB/s eta 0:00:00
2025-11-25 00:11:22.583852 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-25 00:11:22.584066 | controller |   Attempting uninstall: setuptools
2025-11-25 00:11:22.586427 | controller |     Found existing installation: setuptools 62.6.0
2025-11-25 00:11:22.644583 | controller |     Uninstalling setuptools-62.6.0:
2025-11-25 00:11:22.652261 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-25 00:11:23.005278 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-25 00:11:34.543103 | controller |
2025-11-25 00:11:34.625023 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-25 00:11:34.625060 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-25 00:11:34.879425 | controller | ok: Runtime: 0:00:38.116663
2025-11-25 00:11:34.893408 | 
2025-11-25 00:11:34.894249 | TASK [Install pytest-forked into virtualenv]
2025-11-25 00:11:46.809924 | controller | Collecting pytest-forked
2025-11-25 00:12:20.850733 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-25 00:12:20.884687 | controller | Collecting py
2025-11-25 00:12:20.888441 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-25 00:12:20.909400 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.1 MB/s eta 0:00:00
2025-11-25 00:12:21.012132 | controller | Collecting pytest>=3.10
2025-11-25 00:12:21.016353 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-25 00:12:21.028640 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 39.1 MB/s eta 0:00:00
2025-11-25 00:12:21.064647 | controller | Collecting iniconfig>=1.0.1
2025-11-25 00:12:21.067943 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-25 00:12:21.110896 | controller | Collecting packaging>=22
2025-11-25 00:12:21.113969 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-25 00:12:21.119144 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 19.9 MB/s eta 0:00:00
2025-11-25 00:12:21.149444 | controller | Collecting pluggy<2,>=1.5
2025-11-25 00:12:21.152762 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-25 00:12:21.195568 | controller | Collecting pygments>=2.7.2
2025-11-25 00:12:21.198642 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-25 00:12:21.233818 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 40.7 MB/s eta 0:00:00
2025-11-25 00:12:21.302250 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-25 00:12:22.344145 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.1 pytest-forked-1.6.0
2025-11-25 00:12:22.352653 | controller |
2025-11-25 00:12:22.418686 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-25 00:12:22.418720 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-25 00:12:22.486781 | controller | ok: Runtime: 0:00:47.304155
2025-11-25 00:12:22.500862 | 
2025-11-25 00:12:22.501003 | TASK [Update pip]
2025-11-25 00:12:23.029099 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-25 00:12:35.484428 | controller | Collecting pip
2025-11-25 00:12:47.806669 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-25 00:12:47.893020 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 21.9 MB/s eta 0:00:00
2025-11-25 00:12:47.956468 | controller | Installing collected packages: pip
2025-11-25 00:12:47.956627 | controller |   Attempting uninstall: pip
2025-11-25 00:12:47.958843 | controller |     Found existing installation: pip 22.2.2
2025-11-25 00:12:48.101232 | controller |     Uninstalling pip-22.2.2:
2025-11-25 00:12:48.117188 | controller |       Successfully uninstalled pip-22.2.2
2025-11-25 00:12:48.920098 | controller | Successfully installed pip-25.3
2025-11-25 00:12:49.068365 | controller | ok: Runtime: 0:00:26.258290
2025-11-25 00:12:49.085618 | 
2025-11-25 00:12:49.085842 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-25 00:12:49.310915 | controller | changed
2025-11-25 00:12:49.324262 | 
2025-11-25 00:12:49.324420 | TASK [Install ansible into virtualenv]
2025-11-25 00:12:49.826391 | controller | Processing ./src/github.com/ansible/ansible
2025-11-25 00:12:49.829504 | controller |   Installing build dependencies: started
2025-11-25 00:13:12.703088 | controller |   Installing build dependencies: finished with status 'done'
2025-11-25 00:13:12.703643 | controller |   Getting requirements to build wheel: started
2025-11-25 00:13:13.435310 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-25 00:13:13.436564 | controller |   Preparing metadata (pyproject.toml): started
2025-11-25 00:13:13.898643 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-25 00:13:13.903448 | 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-11-25 00:13:13.906753 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-25 00:13:14.386385 | controller | ERROR
2025-11-25 00:13:14.386709 | controller | {
2025-11-25 00:13:14.386813 | controller |   "delta": "0:00:24.422382",
2025-11-25 00:13:14.386857 | controller |   "end": "2025-11-25 00:13:13.978950",
2025-11-25 00:13:14.386895 | controller |   "msg": "non-zero return code",
2025-11-25 00:13:14.386947 | controller |   "rc": 1,
2025-11-25 00:13:14.386983 | controller |   "start": "2025-11-25 00:12:49.556568"
2025-11-25 00:13:14.387017 | controller | }
failure
2025-11-25 00:13:14.390814 | 
2025-11-25 00:13:14.390914 | PLAY RECAP
2025-11-25 00:13:14.390991 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-25 00:13:14.391033 | 
2025-11-25 00:13:14.535544 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-25 00:13:14.536837 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-25 00:13:15.209585 | 
2025-11-25 00:13:15.209709 | PLAY [all]
2025-11-25 00:13:15.233248 | 
2025-11-25 00:13:15.233387 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-25 00:13:15.510045 | controller | changed: non-zero return code
2025-11-25 00:13:15.516799 | 
2025-11-25 00:13:15.517066 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-25 00:13:15.532286 | controller | skipping: Conditional result was False
2025-11-25 00:13:15.539761 | 
2025-11-25 00:13:15.539879 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-25 00:13:15.573304 | 
2025-11-25 00:13:15.573472 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-25 00:13:15.605284 | 
2025-11-25 00:13:15.605454 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-25 00:13:15.630207 | controller | skipping: Conditional result was False
2025-11-25 00:13:15.638351 | 
2025-11-25 00:13:15.638448 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-25 00:13:15.669040 | 
2025-11-25 00:13:15.669193 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-25 00:13:15.694533 | controller | skipping: Conditional result was False
2025-11-25 00:13:15.705477 | 
2025-11-25 00:13:15.705615 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-25 00:13:15.731979 | controller | skipping: Conditional result was False
2025-11-25 00:13:15.742530 | 
2025-11-25 00:13:15.742669 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-25 00:13:15.768600 | controller | skipping: Conditional result was False
2025-11-25 00:13:15.796102 | 
2025-11-25 00:13:15.796191 | PLAY RECAP
2025-11-25 00:13:15.796237 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-25 00:13:15.796258 | 
2025-11-25 00:13:15.897442 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-25 00:13:15.898325 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-25 00:13:16.477611 | 
2025-11-25 00:13:16.477758 | PLAY [all:!appliance*]
2025-11-25 00:13:16.499320 | 
2025-11-25 00:13:16.499423 | TASK [unregister the node]
2025-11-25 00:13:17.032377 | controller | skipping: Conditional result was False
2025-11-25 00:13:17.049577 | 
2025-11-25 00:13:17.049939 | TASK [include_role : fetch-output]
2025-11-25 00:13:17.102315 | controller | ok
2025-11-25 00:13:17.144845 | 
2025-11-25 00:13:17.144991 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-25 00:13:17.221520 | controller | skipping: Conditional result was False
2025-11-25 00:13:17.230966 | 
2025-11-25 00:13:17.231090 | TASK [fetch-output : Set log path for single node]
2025-11-25 00:13:17.277136 | controller | ok
2025-11-25 00:13:17.283540 | 
2025-11-25 00:13:17.283663 | LOOP [fetch-output : Ensure local output dirs]
2025-11-25 00:13:17.727841 | controller -> localhost | ok: "/var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/logs"
2025-11-25 00:13:18.018861 | controller -> localhost | changed: "/var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/artifacts"
2025-11-25 00:13:18.285922 | controller -> localhost | changed: "/var/lib/zuul/builds/53f39a5c011e494c98a2da3d3dbfc401/work/docs"
2025-11-25 00:13:18.308825 | 
2025-11-25 00:13:18.309045 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-25 00:13:19.061502 | controller | changed:
2025-11-25 00:13:19.061835 | controller | .d..t...... ./
2025-11-25 00:13:19.061881 | controller | cd+++++++++ controller/
2025-11-25 00:13:19.061927 | controller | changed: All items complete
2025-11-25 00:13:19.061956 | 
2025-11-25 00:13:19.601444 | controller | changed: .d..t...... ./
2025-11-25 00:13:20.139361 | controller | changed: .d..t...... ./
2025-11-25 00:13:20.160179 | 
2025-11-25 00:13:20.160359 | TASK [include_role : fetch-output-openshift]
2025-11-25 00:13:20.186590 | controller | skipping: Conditional result was False
2025-11-25 00:13:20.194275 | 
2025-11-25 00:13:20.194405 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-25 00:13:20.237770 | controller | skipping: Conditional result was False
2025-11-25 00:13:20.250025 | controller | skipping: Conditional result was False
2025-11-25 00:13:20.311435 | 
2025-11-25 00:13:20.311616 | PLAY [localhost]
2025-11-25 00:13:20.336893 | 
2025-11-25 00:13:20.337047 | TASK [Run Zuul manifest role]
2025-11-25 00:13:20.357334 | localhost | ok
2025-11-25 00:13:20.372028 | 
2025-11-25 00:13:20.372141 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-25 00:13:20.838803 | localhost | changed
2025-11-25 00:13:20.844365 | 
2025-11-25 00:13:20.844463 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-25 00:13:20.874469 | localhost | ok
2025-11-25 00:13:20.884017 | 
2025-11-25 00:13:20.884112 | TASK [Set zuul-log-path fact]
2025-11-25 00:13:20.904361 | localhost | ok
2025-11-25 00:13:20.921077 | 
2025-11-25 00:13:20.921229 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-25 00:13:20.961979 | localhost | ok
2025-11-25 00:13:20.972454 | 
2025-11-25 00:13:20.972544 | LOOP [Run upload-logs-swift role]
2025-11-25 00:13:20.999459 | localhost | Output suppressed because no_log was given
2025-11-25 00:13:21.041407 | 
2025-11-25 00:13:21.041563 | TASK [Set zuul-log-path fact]
2025-11-25 00:13:21.067102 | localhost | skipping: Conditional result was False
2025-11-25 00:13:21.072981 | 
2025-11-25 00:13:21.073078 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-25 00:13:21.468288 | localhost -> localhost | ok: Runtime: 0:00:00.005203
2025-11-25 00:13:21.516276 | 
2025-11-25 00:13:21.516426 | TASK [upload-logs-swift : Upload logs to swift]