2026-01-02 00:07:45.379375 | Job console starting...
2026-01-02 00:07:45.391964 | Updating repositories
2026-01-02 00:07:45.557802 | Preparing job workspace
2026-01-02 00:07:55.705784 | Running Ansible setup...
2026-01-02 00:08:04.495959 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-02 00:08:05.121506 | 
2026-01-02 00:08:05.121637 | PLAY [localhost]
2026-01-02 00:08:05.130950 | 
2026-01-02 00:08:05.131087 | TASK [Gathering Facts]
2026-01-02 00:08:06.114128 | localhost | ok
2026-01-02 00:08:06.127655 | 
2026-01-02 00:08:06.127759 | TASK [Setup log path fact]
2026-01-02 00:08:06.155538 | localhost | ok
2026-01-02 00:08:06.168207 | 
2026-01-02 00:08:06.168283 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-02 00:08:06.195972 | localhost | ok
2026-01-02 00:08:06.204146 | 
2026-01-02 00:08:06.204233 | TASK [emit-job-header : Print job information]
2026-01-02 00:08:06.234580 | # Job Information
2026-01-02 00:08:06.234793 | Ansible Version: 2.15.12
2026-01-02 00:08:06.234841 | Job: ansible-test-sanity-docker-milestone
2026-01-02 00:08:06.234874 | Pipeline: periodic
2026-01-02 00:08:06.234904 | Executor: ze01.softwarefactory-project.io
2026-01-02 00:08:06.234933 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-02 00:08:06.234967 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/60b/ansible/60b780aac0784c43b95854795c6e8463/
2026-01-02 00:08:06.234997 | Event ID: c804f0f0b15c4818b5153ddc52d4da2c
2026-01-02 00:08:06.240997 | 
2026-01-02 00:08:06.241114 | LOOP [emit-job-header : Print node information]
2026-01-02 00:08:06.348244 | localhost | ok:
2026-01-02 00:08:06.348438 | localhost | # Node Information
2026-01-02 00:08:06.348465 | localhost | Inventory Hostname: controller
2026-01-02 00:08:06.348485 | localhost | Hostname: np0005573262
2026-01-02 00:08:06.348503 | localhost | Username: zuul
2026-01-02 00:08:06.348524 | localhost | Distro: Fedora 37
2026-01-02 00:08:06.348542 | localhost | Provider: ansible-vexxhost-ams1
2026-01-02 00:08:06.348558 | localhost | Region: ams1
2026-01-02 00:08:06.348575 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-02 00:08:06.348591 | localhost | Product Name: OpenStack Nova
2026-01-02 00:08:06.348607 | localhost | Interface IP: 38.129.16.68
2026-01-02 00:08:06.366875 | 
2026-01-02 00:08:06.367051 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-02 00:08:06.748063 | localhost -> localhost | changed
2026-01-02 00:08:06.753770 | 
2026-01-02 00:08:06.753851 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-02 00:08:07.795253 | localhost -> localhost | changed
2026-01-02 00:08:07.842809 | 
2026-01-02 00:08:07.842936 | PLAY [all:!appliance*]
2026-01-02 00:08:07.867802 | 
2026-01-02 00:08:07.867936 | TASK [include_role : start-zuul-console]
2026-01-02 00:08:07.890494 | controller | ok
2026-01-02 00:08:07.913187 | 
2026-01-02 00:08:07.913314 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-02 00:08:08.971831 | controller | ok
2026-01-02 00:08:08.991003 | 
2026-01-02 00:08:08.991219 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-02 00:08:11.338632 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-02 00:08:11.351510 | 
2026-01-02 00:08:11.351654 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-02 00:08:11.721338 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.730924 | 
2026-01-02 00:08:11.731078 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-02 00:08:11.766722 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.774626 | 
2026-01-02 00:08:11.774744 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-02 00:08:11.799746 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.809419 | 
2026-01-02 00:08:11.809543 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-02 00:08:11.834457 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.841155 | 
2026-01-02 00:08:11.841249 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-02 00:08:11.864522 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.873771 | 
2026-01-02 00:08:11.873903 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-02 00:08:11.898993 | controller | skipping: Conditional result was False
2026-01-02 00:08:11.915489 | 
2026-01-02 00:08:11.915626 | TASK [Disable Fedora Modular]
2026-01-02 00:08:13.227474 | controller | changed
2026-01-02 00:08:13.237609 | 
2026-01-02 00:08:13.237750 | TASK [Enable EPEL]
2026-01-02 00:08:13.254403 | controller | skipping: Conditional result was False
2026-01-02 00:08:13.265650 | 
2026-01-02 00:08:13.265781 | TASK [Register the RHEL node]
2026-01-02 00:08:13.682705 | 
2026-01-02 00:08:13.682875 | TASK [Show the subscription-manager status]
2026-01-02 00:08:14.043244 | controller | skipping: Conditional result was False
2026-01-02 00:08:14.051090 | 
2026-01-02 00:08:14.051218 | TASK [Enable EPEL on RHEL]
2026-01-02 00:08:14.427137 | controller | skipping: Conditional result was False
2026-01-02 00:08:14.433829 | 
2026-01-02 00:08:14.433944 | TASK [Install git and tox]
2026-01-02 00:10:29.039810 | controller | changed
2026-01-02 00:10:29.046689 | 
2026-01-02 00:10:29.046775 | TASK [include_role : prepare-workspace]
2026-01-02 00:10:29.084597 | controller | ok
2026-01-02 00:10:29.117318 | 
2026-01-02 00:10:29.117618 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-02 00:10:29.965943 | controller | ok
2026-01-02 00:10:29.974054 | 
2026-01-02 00:10:29.974145 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-02 00:10:45.712442 | controller | Output suppressed because no_log was given
2026-01-02 00:10:45.765738 | 
2026-01-02 00:10:45.765876 | TASK [include_role : prepare-workspace-openshift]
2026-01-02 00:10:45.811647 | controller | skipping: Conditional result was False
2026-01-02 00:10:45.833850 | 
2026-01-02 00:10:45.833936 | PLAY [all:!appliance]
2026-01-02 00:10:45.851532 | 
2026-01-02 00:10:45.851654 | TASK [Run add-build-sshkey role (RSA)]
2026-01-02 00:10:45.881766 | controller | ok
2026-01-02 00:10:45.896466 | 
2026-01-02 00:10:45.896579 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-02 00:10:46.137759 | controller -> localhost | ok
2026-01-02 00:10:46.144776 | 
2026-01-02 00:10:46.144908 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-02 00:10:46.175091 | controller | ok
2026-01-02 00:10:46.190382 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-02 00:10:46.197046 | 
2026-01-02 00:10:46.197167 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-02 00:10:46.727840 | controller -> localhost | Generating public/private rsa key pair.
2026-01-02 00:10:46.728183 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_rsa.
2026-01-02 00:10:46.728226 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_rsa.pub.
2026-01-02 00:10:46.728257 | controller -> localhost | The key fingerprint is:
2026-01-02 00:10:46.728285 | controller -> localhost | SHA256:GLdPXkvWcbYge5JAdE/UgYVJslbL97hsWil5EnxtTvs zuul-build-sshkey
2026-01-02 00:10:46.728313 | controller -> localhost | The key's randomart image is:
2026-01-02 00:10:46.728340 | controller -> localhost | +---[RSA 2048]----+
2026-01-02 00:10:46.728364 | controller -> localhost | |        .o oo=*o.|
2026-01-02 00:10:46.728391 | controller -> localhost | |        . . B+.. |
2026-01-02 00:10:46.728417 | controller -> localhost | |      . .. + =..o|
2026-01-02 00:10:46.728440 | controller -> localhost | |       + .o.+.o*o|
2026-01-02 00:10:46.728464 | controller -> localhost | |      . S .+*.+.=|
2026-01-02 00:10:46.728506 | controller -> localhost | |         + +o* *.|
2026-01-02 00:10:46.728538 | controller -> localhost | |          o = B..|
2026-01-02 00:10:46.728562 | controller -> localhost | |             B  .|
2026-01-02 00:10:46.728582 | controller -> localhost | |            .   E|
2026-01-02 00:10:46.728622 | controller -> localhost | +----[SHA256]-----+
2026-01-02 00:10:46.728675 | controller -> localhost | ok: Runtime: 0:00:00.101518
2026-01-02 00:10:46.757768 | 
2026-01-02 00:10:46.757973 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-02 00:10:46.790824 | controller | ok
2026-01-02 00:10:46.803098 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-02 00:10:46.815403 | 
2026-01-02 00:10:46.815543 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-02 00:10:46.841952 | controller | skipping: Conditional result was False
2026-01-02 00:10:46.848918 | 
2026-01-02 00:10:46.849035 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-02 00:10:48.039444 | controller | changed
2026-01-02 00:10:48.048764 | 
2026-01-02 00:10:48.048920 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-02 00:10:48.752934 | controller | ok
2026-01-02 00:10:48.766904 | 
2026-01-02 00:10:48.767154 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-02 00:10:51.836484 | controller | changed
2026-01-02 00:10:51.844581 | 
2026-01-02 00:10:51.844747 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-02 00:10:54.906055 | controller | changed
2026-01-02 00:10:54.913919 | 
2026-01-02 00:10:54.914034 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-02 00:10:54.939738 | controller | skipping: Conditional result was False
2026-01-02 00:10:54.948687 | 
2026-01-02 00:10:54.948858 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-02 00:10:55.363204 | controller -> localhost | changed
2026-01-02 00:10:55.382535 | 
2026-01-02 00:10:55.382727 | TASK [add-build-sshkey : Add back temp key]
2026-01-02 00:10:55.745759 | controller -> localhost | Identity added: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_rsa (zuul-build-sshkey)
2026-01-02 00:10:55.746062 | controller -> localhost | ok: Runtime: 0:00:00.009616
2026-01-02 00:10:55.759920 | 
2026-01-02 00:10:55.760064 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-02 00:10:56.782487 | controller | ok
2026-01-02 00:10:56.795052 | 
2026-01-02 00:10:56.795213 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-02 00:10:56.843596 | controller | skipping: Conditional result was False
2026-01-02 00:10:56.861089 | 
2026-01-02 00:10:56.861276 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-02 00:10:56.898373 | controller | ok
2026-01-02 00:10:56.922600 | 
2026-01-02 00:10:56.922758 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-02 00:10:57.196287 | controller -> localhost | ok
2026-01-02 00:10:57.212131 | 
2026-01-02 00:10:57.212345 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-02 00:10:57.256535 | controller | ok
2026-01-02 00:10:57.280056 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-02 00:10:57.290971 | 
2026-01-02 00:10:57.291134 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-02 00:10:57.615956 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-02 00:10:57.616194 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_ecdsa.
2026-01-02 00:10:57.616230 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_ecdsa.pub.
2026-01-02 00:10:57.616265 | controller -> localhost | The key fingerprint is:
2026-01-02 00:10:57.616286 | controller -> localhost | SHA256:1Nlx7ko7m0tD5wsJv0OxE44lXRvHMr+52IDT6VPc2wM zuul-build-sshkey
2026-01-02 00:10:57.616309 | controller -> localhost | The key's randomart image is:
2026-01-02 00:10:57.616329 | controller -> localhost | +---[ECDSA 521]---+
2026-01-02 00:10:57.616348 | controller -> localhost | |            . .. |
2026-01-02 00:10:57.616366 | controller -> localhost | |         . o += o|
2026-01-02 00:10:57.616385 | controller -> localhost | |        . o....B |
2026-01-02 00:10:57.616403 | controller -> localhost | |       .  . =.. .|
2026-01-02 00:10:57.616421 | controller -> localhost | |        S .==+= +|
2026-01-02 00:10:57.616439 | controller -> localhost | |          .B=E =.|
2026-01-02 00:10:57.616457 | controller -> localhost | |           .%.B +|
2026-01-02 00:10:57.616477 | controller -> localhost | |           ..@ *.|
2026-01-02 00:10:57.616505 | controller -> localhost | |            =oo .|
2026-01-02 00:10:57.616535 | controller -> localhost | +----[SHA256]-----+
2026-01-02 00:10:57.616609 | controller -> localhost | ok: Runtime: 0:00:00.010294
2026-01-02 00:10:57.624428 | 
2026-01-02 00:10:57.624540 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-02 00:10:57.657649 | controller | ok
2026-01-02 00:10:57.669781 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-02 00:10:57.684359 | 
2026-01-02 00:10:57.684528 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-02 00:10:57.710286 | controller | skipping: Conditional result was False
2026-01-02 00:10:57.765154 | 
2026-01-02 00:10:57.765335 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-02 00:10:58.700173 | controller | changed
2026-01-02 00:10:58.709441 | 
2026-01-02 00:10:58.709639 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-02 00:10:59.412003 | controller | ok
2026-01-02 00:10:59.423080 | 
2026-01-02 00:10:59.423285 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-02 00:11:02.514532 | controller | changed
2026-01-02 00:11:02.521052 | 
2026-01-02 00:11:02.521130 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-02 00:11:05.564179 | controller | changed
2026-01-02 00:11:05.580106 | 
2026-01-02 00:11:05.580361 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-02 00:11:05.608888 | controller | skipping: Conditional result was False
2026-01-02 00:11:05.619553 | 
2026-01-02 00:11:05.619732 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-02 00:11:05.915452 | controller -> localhost | changed
2026-01-02 00:11:05.955864 | 
2026-01-02 00:11:05.956061 | TASK [add-build-sshkey : Add back temp key]
2026-01-02 00:11:06.271490 | controller -> localhost | Identity added: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/60b780aac0784c43b95854795c6e8463_id_ecdsa (zuul-build-sshkey)
2026-01-02 00:11:06.271828 | controller -> localhost | ok: Runtime: 0:00:00.010332
2026-01-02 00:11:06.280451 | 
2026-01-02 00:11:06.280599 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-02 00:11:06.994033 | controller | ok
2026-01-02 00:11:07.003134 | 
2026-01-02 00:11:07.003271 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-02 00:11:07.029327 | controller | skipping: Conditional result was False
2026-01-02 00:11:07.048567 | 
2026-01-02 00:11:07.048759 | TASK [include_role : remove-zuul-sshkey]
2026-01-02 00:11:07.075591 | controller | skipping: Conditional result was False
2026-01-02 00:11:07.088453 | 
2026-01-02 00:11:07.088633 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-02 00:11:07.743128 | controller | ok: "logs"
2026-01-02 00:11:07.743662 | controller | ok: All items complete
2026-01-02 00:11:07.743727 | 
2026-01-02 00:11:08.365931 | controller | ok: "artifacts"
2026-01-02 00:11:08.997361 | controller | ok: "docs"
2026-01-02 00:11:09.015664 | 
2026-01-02 00:11:09.015866 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-02 00:11:09.732982 | controller | changed: "logs"
2026-01-02 00:11:10.385383 | controller | changed: "artifacts"
2026-01-02 00:11:11.003894 | controller | changed: "docs"
2026-01-02 00:11:11.044750 | 
2026-01-02 00:11:11.044900 | PLAY RECAP
2026-01-02 00:11:11.044961 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-02 00:11:11.044994 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-02 00:11:11.045076 | 
2026-01-02 00:11:11.247587 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-02 00:11:11.248555 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-02 00:11:11.906334 | 
2026-01-02 00:11:11.906492 | PLAY [all]
2026-01-02 00:11:11.930202 | 
2026-01-02 00:11:11.930373 | TASK [Install binary dependencies]
2026-01-02 00:11:11.981715 | controller | ok
2026-01-02 00:11:12.002179 | 
2026-01-02 00:11:12.002342 | TASK [bindep : Include find tasks]
2026-01-02 00:11:12.033459 | controller | ok
2026-01-02 00:11:12.043921 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-02 00:11:12.050597 | 
2026-01-02 00:11:12.050725 | TASK [bindep : Look for bindep.txt]
2026-01-02 00:11:13.017584 | controller | ok
2026-01-02 00:11:13.023659 | 
2026-01-02 00:11:13.023740 | TASK [bindep : Define bindep_file fact]
2026-01-02 00:11:13.047996 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.056384 | 
2026-01-02 00:11:13.056527 | TASK [bindep : Look for other-requirements.txt]
2026-01-02 00:11:13.722337 | controller | ok
2026-01-02 00:11:13.728815 | 
2026-01-02 00:11:13.728890 | TASK [bindep : Define bindep_file fact]
2026-01-02 00:11:13.753245 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.761640 | 
2026-01-02 00:11:13.761737 | TASK [bindep : Look for bindep fallback file]
2026-01-02 00:11:13.785903 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.792787 | 
2026-01-02 00:11:13.792880 | TASK [bindep : Define bindep_file fact]
2026-01-02 00:11:13.816767 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.823242 | 
2026-01-02 00:11:13.823314 | TASK [bindep : Include bindep tasks]
2026-01-02 00:11:13.847802 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.854995 | 
2026-01-02 00:11:13.855107 | TASK [bindep : Include install tasks]
2026-01-02 00:11:13.879644 | controller | skipping: Conditional result was False
2026-01-02 00:11:13.886846 | 
2026-01-02 00:11:13.886927 | LOOP [bindep : Include package tasks]
2026-01-02 00:11:13.944202 | 
2026-01-02 00:11:13.944382 | TASK [Run test-setup role]
2026-01-02 00:11:13.969323 | controller | ok
2026-01-02 00:11:13.994261 | 
2026-01-02 00:11:13.994422 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-02 00:11:14.747947 | controller | ok
2026-01-02 00:11:14.754540 | 
2026-01-02 00:11:14.754655 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-02 00:11:15.139954 | controller | skipping: Conditional result was False
2026-01-02 00:11:15.182597 | 
2026-01-02 00:11:15.182762 | PLAY RECAP
2026-01-02 00:11:15.182849 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-02 00:11:15.182898 | 
2026-01-02 00:11:15.335828 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-02 00:11:15.337265 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-02 00:11:15.975239 | 
2026-01-02 00:11:15.975401 | PLAY [controller]
2026-01-02 00:11:15.998724 | 
2026-01-02 00:11:15.998883 | TASK [Create the /root directory]
2026-01-02 00:11:17.162928 | controller | ok
2026-01-02 00:11:17.169304 | 
2026-01-02 00:11:17.169396 | TASK [Install glibc-langpack-en]
2026-01-02 00:11:25.805560 | controller | ok: Nothing to do
2026-01-02 00:11:25.811881 | 
2026-01-02 00:11:25.811978 | TASK [Ensure controller directory exists]
2026-01-02 00:11:26.623193 | controller | changed
2026-01-02 00:11:26.629514 | 
2026-01-02 00:11:26.629592 | TASK [Install container runtime]
2026-01-02 00:11:26.710164 | controller | ok
2026-01-02 00:11:26.768509 | 
2026-01-02 00:11:26.768646 | LOOP [ensure-podman : Find distribution installation]
2026-01-02 00:11:26.801269 | controller | ok: "/var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-02 00:11:26.819628 | controller | included: /var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-02 00:11:26.830607 | 
2026-01-02 00:11:26.830712 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-02 00:13:30.928370 | controller | changed
2026-01-02 00:13:30.945930 | 
2026-01-02 00:13:30.946174 | TASK [ensure-podman : Fetch podman version]
2026-01-02 00:13:32.189397 | controller | Client:       Podman Engine
2026-01-02 00:13:32.231492 | controller | Version:      4.6.2
2026-01-02 00:13:32.231546 | controller | API Version:  4.6.2
2026-01-02 00:13:32.231555 | controller | Go Version:   go1.19.12
2026-01-02 00:13:32.231576 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-02 00:13:32.231584 | controller | OS/Arch:      linux/amd64
2026-01-02 00:13:32.828836 | controller | ok: Runtime: 0:00:00.325639
2026-01-02 00:13:32.836784 | 
2026-01-02 00:13:32.836881 | TASK [ensure-podman : Print podman version installed]
2026-01-02 00:13:32.875633 | Podman version: Client:       Podman Engine
2026-01-02 00:13:32.875880 | Version:      4.6.2
2026-01-02 00:13:32.875920 | API Version:  4.6.2
2026-01-02 00:13:32.875947 | Go Version:   go1.19.12
2026-01-02 00:13:32.875973 | Built:        Mon Aug 28 19:38:31 2023
2026-01-02 00:13:32.876001 | OS/Arch:      linux/amd64
2026-01-02 00:13:32.884319 | 
2026-01-02 00:13:32.884414 | TASK [ensure-podman : Validate podman engine]
2026-01-02 00:13:33.253508 | controller | skipping: Conditional result was False
2026-01-02 00:13:33.269254 | 
2026-01-02 00:13:33.270056 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-02 00:13:33.297190 | controller | skipping: Conditional result was False
2026-01-02 00:13:33.313084 | 
2026-01-02 00:13:33.313273 | TASK [Ensure python3.8 is present]
2026-01-02 00:13:33.329830 | controller | skipping: Conditional result was False
2026-01-02 00:13:33.338063 | 
2026-01-02 00:13:33.338159 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-02 00:13:33.360572 | controller | ok
2026-01-02 00:13:33.380342 | 
2026-01-02 00:13:33.380485 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-02 00:13:36.990983 | controller | ok: Nothing to do
2026-01-02 00:13:37.000061 | 
2026-01-02 00:13:37.000188 | TASK [our-ensure-python : Also install python3-devel]
2026-01-02 00:13:52.168683 | controller | changed
2026-01-02 00:13:52.180985 | 
2026-01-02 00:13:52.181211 | TASK [Run ensure-virtualenv role]
2026-01-02 00:13:52.207174 | controller | ok
2026-01-02 00:13:52.238895 | 
2026-01-02 00:13:52.239159 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-02 00:13:53.073234 | controller | /usr/bin/virtualenv
2026-01-02 00:13:53.652010 | controller | ok: Runtime: 0:00:00.007007
2026-01-02 00:13:53.667802 | 
2026-01-02 00:13:53.667996 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-02 00:13:53.699844 | controller | skipping: Conditional result was False
2026-01-02 00:13:53.700302 | controller | ok: All items complete
2026-01-02 00:13:53.700343 | 
2026-01-02 00:13:53.724313 | 
2026-01-02 00:13:53.724516 | TASK [Find the full path of the Python interpreter]
2026-01-02 00:13:54.576184 | controller | /usr/bin/python3
2026-01-02 00:13:55.091400 | controller | ok
2026-01-02 00:13:55.100208 | 
2026-01-02 00:13:55.100379 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-02 00:13:56.902438 | controller | created virtual environment CPython3.11.0.final.0-64 in 905ms
2026-01-02 00:13:56.967474 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-02 00:13:56.967532 | 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)
2026-01-02 00:13:56.967546 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-02 00:13:56.967567 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-02 00:13:57.491506 | controller | changed
2026-01-02 00:13:57.499377 | 
2026-01-02 00:13:57.499508 | TASK [Set selinux package]
2026-01-02 00:13:57.522967 | controller | ok
2026-01-02 00:13:57.529953 | 
2026-01-02 00:13:57.530081 | TASK [Set selinux package (Fedora)]
2026-01-02 00:13:57.562690 | controller | ok
2026-01-02 00:13:57.568977 | 
2026-01-02 00:13:57.569122 | TASK [Install selinux into virtualenv]
2026-01-02 00:14:00.634674 | controller | Collecting selinux-please-lie-to-me
2026-01-02 00:14:00.699181 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-02 00:14:01.205499 | controller | Collecting setuptools<50.0.0
2026-01-02 00:14:01.215306 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-02 00:14:01.270874 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 16.3 MB/s eta 0:00:00
2026-01-02 00:14:01.404703 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-02 00:14:01.404904 | controller |   Attempting uninstall: setuptools
2026-01-02 00:14:01.408639 | controller |     Found existing installation: setuptools 62.6.0
2026-01-02 00:14:01.516032 | controller |     Uninstalling setuptools-62.6.0:
2026-01-02 00:14:01.530316 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-02 00:14:02.293607 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-02 00:14:02.513302 | controller |
2026-01-02 00:14:02.847919 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-02 00:14:02.847963 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-02 00:14:03.458423 | controller | ok: Runtime: 0:00:04.500942
2026-01-02 00:14:03.466965 | 
2026-01-02 00:14:03.467215 | TASK [Install pytest-forked into virtualenv]
2026-01-02 00:14:04.965120 | controller | Collecting pytest-forked
2026-01-02 00:14:05.038056 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-02 00:14:05.099227 | controller | Collecting py
2026-01-02 00:14:05.104132 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-02 00:14:05.139201 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00
2026-01-02 00:14:05.353440 | controller | Collecting pytest>=3.10
2026-01-02 00:14:05.360145 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-02 00:14:05.397305 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 14.4 MB/s eta 0:00:00
2026-01-02 00:14:05.486219 | controller | Collecting iniconfig>=1.0.1
2026-01-02 00:14:05.492616 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-02 00:14:05.565038 | controller | Collecting packaging>=22
2026-01-02 00:14:05.570005 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2026-01-02 00:14:05.587493 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.3 MB/s eta 0:00:00
2026-01-02 00:14:05.653450 | controller | Collecting pluggy<2,>=1.5
2026-01-02 00:14:05.657790 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-02 00:14:05.735212 | controller | Collecting pygments>=2.7.2
2026-01-02 00:14:05.741545 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-02 00:14:05.764622 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 61.7 MB/s eta 0:00:00
2026-01-02 00:14:05.928844 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-02 00:14:08.245271 | 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.2 pytest-forked-1.6.0
2026-01-02 00:14:08.259024 | controller |
2026-01-02 00:14:08.492949 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-02 00:14:08.493013 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-02 00:14:08.861863 | controller | ok: Runtime: 0:00:04.239256
2026-01-02 00:14:08.870491 | 
2026-01-02 00:14:08.870651 | TASK [Update pip]
2026-01-02 00:14:10.290073 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-02 00:14:10.607665 | controller | Collecting pip
2026-01-02 00:14:10.692462 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-02 00:14:10.774208 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 22.9 MB/s eta 0:00:00
2026-01-02 00:14:10.921240 | controller | Installing collected packages: pip
2026-01-02 00:14:10.927007 | controller |   Attempting uninstall: pip
2026-01-02 00:14:10.927043 | controller |     Found existing installation: pip 22.2.2
2026-01-02 00:14:11.173179 | controller |     Uninstalling pip-22.2.2:
2026-01-02 00:14:11.203992 | controller |       Successfully uninstalled pip-22.2.2
2026-01-02 00:14:13.069342 | controller | Successfully installed pip-25.3
2026-01-02 00:14:13.752682 | controller | ok: Runtime: 0:00:03.647042
2026-01-02 00:14:13.767343 | 
2026-01-02 00:14:13.767498 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-02 00:14:14.626787 | controller | changed
2026-01-02 00:14:14.640243 | 
2026-01-02 00:14:14.640403 | TASK [Install ansible into virtualenv]
2026-01-02 00:14:15.863808 | controller | Processing ./src/github.com/ansible/ansible
2026-01-02 00:14:15.869853 | controller |   Installing build dependencies: started
2026-01-02 00:14:17.896500 | controller |   Installing build dependencies: finished with status 'done'
2026-01-02 00:14:19.402353 | controller |   Getting requirements to build wheel: started
2026-01-02 00:14:19.402418 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-02 00:14:19.403412 | controller |   Preparing metadata (pyproject.toml): started
2026-01-02 00:14:20.322710 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-02 00:14:20.324551 | 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.
2026-01-02 00:14:20.331367 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-02 00:14:21.024816 | controller | ERROR
2026-01-02 00:14:21.025149 | controller | {
2026-01-02 00:14:21.025187 | controller |   "delta": "0:00:05.208789",
2026-01-02 00:14:21.025208 | controller |   "end": "2026-01-02 00:14:20.508782",
2026-01-02 00:14:21.025225 | controller |   "msg": "non-zero return code",
2026-01-02 00:14:21.025267 | controller |   "rc": 1,
2026-01-02 00:14:21.025284 | controller |   "start": "2026-01-02 00:14:15.299993"
2026-01-02 00:14:21.025299 | controller | }
failure
2026-01-02 00:14:21.027303 | 
2026-01-02 00:14:21.027361 | PLAY RECAP
2026-01-02 00:14:21.027408 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-02 00:14:21.027430 | 
2026-01-02 00:14:21.212006 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-02 00:14:21.213119 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-02 00:14:21.901611 | 
2026-01-02 00:14:21.901794 | PLAY [all]
2026-01-02 00:14:21.925238 | 
2026-01-02 00:14:21.925434 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-02 00:14:23.816848 | controller | changed: non-zero return code
2026-01-02 00:14:23.831375 | 
2026-01-02 00:14:23.831500 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-02 00:14:23.847216 | controller | skipping: Conditional result was False
2026-01-02 00:14:23.856532 | 
2026-01-02 00:14:23.856638 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-02 00:14:23.882588 | 
2026-01-02 00:14:23.882792 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-02 00:14:23.910310 | 
2026-01-02 00:14:23.910592 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-02 00:14:23.928441 | controller | skipping: Conditional result was False
2026-01-02 00:14:23.938646 | 
2026-01-02 00:14:23.938788 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-02 00:14:23.974302 | 
2026-01-02 00:14:23.974572 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-02 00:14:23.992106 | controller | skipping: Conditional result was False
2026-01-02 00:14:24.002122 | 
2026-01-02 00:14:24.002336 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-02 00:14:24.019797 | controller | skipping: Conditional result was False
2026-01-02 00:14:24.029931 | 
2026-01-02 00:14:24.030336 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-02 00:14:24.057270 | controller | skipping: Conditional result was False
2026-01-02 00:14:24.086856 | 
2026-01-02 00:14:24.087006 | PLAY RECAP
2026-01-02 00:14:24.087099 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-02 00:14:24.087122 | 
2026-01-02 00:14:24.248507 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-02 00:14:24.249720 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-02 00:14:24.915203 | 
2026-01-02 00:14:24.915425 | PLAY [all:!appliance*]
2026-01-02 00:14:24.946681 | 
2026-01-02 00:14:24.946874 | TASK [unregister the node]
2026-01-02 00:14:25.304365 | controller | skipping: Conditional result was False
2026-01-02 00:14:25.311475 | 
2026-01-02 00:14:25.311579 | TASK [include_role : fetch-output]
2026-01-02 00:14:25.344843 | controller | ok
2026-01-02 00:14:25.368869 | 
2026-01-02 00:14:25.369064 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-02 00:14:25.445506 | controller | skipping: Conditional result was False
2026-01-02 00:14:25.452307 | 
2026-01-02 00:14:25.452435 | TASK [fetch-output : Set log path for single node]
2026-01-02 00:14:25.495082 | controller | ok
2026-01-02 00:14:25.502231 | 
2026-01-02 00:14:25.502376 | LOOP [fetch-output : Ensure local output dirs]
2026-01-02 00:14:25.899553 | controller -> localhost | ok: "/var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/logs"
2026-01-02 00:14:26.134149 | controller -> localhost | changed: "/var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/artifacts"
2026-01-02 00:14:26.408812 | controller -> localhost | changed: "/var/lib/zuul/builds/60b780aac0784c43b95854795c6e8463/work/docs"
2026-01-02 00:14:26.422755 | 
2026-01-02 00:14:26.422955 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-02 00:14:28.722918 | controller | changed:
2026-01-02 00:14:28.723833 | controller | .d..t...... ./
2026-01-02 00:14:28.724158 | controller | cd+++++++++ controller/
2026-01-02 00:14:28.724267 | controller | changed: All items complete
2026-01-02 00:14:28.724316 | 
2026-01-02 00:14:30.934225 | controller | changed: .d..t...... ./
2026-01-02 00:14:33.059075 | controller | changed: .d..t...... ./
2026-01-02 00:14:33.098148 | 
2026-01-02 00:14:33.098450 | TASK [include_role : fetch-output-openshift]
2026-01-02 00:14:33.128386 | controller | skipping: Conditional result was False
2026-01-02 00:14:33.145732 | 
2026-01-02 00:14:33.145908 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-02 00:14:33.195044 | controller | skipping: Conditional result was False
2026-01-02 00:14:33.207331 | controller | skipping: Conditional result was False
2026-01-02 00:14:33.264971 | 
2026-01-02 00:14:33.265187 | PLAY [localhost]
2026-01-02 00:14:33.286537 | 
2026-01-02 00:14:33.286702 | TASK [Run Zuul manifest role]
2026-01-02 00:14:33.310101 | localhost | ok
2026-01-02 00:14:33.330817 | 
2026-01-02 00:14:33.330936 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-02 00:14:33.782556 | localhost | changed
2026-01-02 00:14:33.789283 | 
2026-01-02 00:14:33.789454 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-02 00:14:33.843825 | localhost | ok
2026-01-02 00:14:33.857184 | 
2026-01-02 00:14:33.857300 | TASK [Set zuul-log-path fact]
2026-01-02 00:14:33.923810 | localhost | ok
2026-01-02 00:14:33.938284 | 
2026-01-02 00:14:33.938383 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-02 00:14:33.981389 | localhost | ok
2026-01-02 00:14:33.990643 | 
2026-01-02 00:14:33.990765 | LOOP [Run upload-logs-swift role]
2026-01-02 00:14:34.016996 | localhost | Output suppressed because no_log was given
2026-01-02 00:14:34.044728 | 
2026-01-02 00:14:34.044876 | TASK [Set zuul-log-path fact]
2026-01-02 00:14:34.071468 | localhost | skipping: Conditional result was False
2026-01-02 00:14:34.078481 | 
2026-01-02 00:14:34.078685 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-02 00:14:34.503154 | localhost -> localhost | ok: Runtime: 0:00:00.010691
2026-01-02 00:14:34.518603 | 
2026-01-02 00:14:34.518906 | TASK [upload-logs-swift : Upload logs to swift]