2025-10-01 00:06:36.469902 | Job console starting...
2025-10-01 00:06:36.485439 | Updating repositories
2025-10-01 00:06:36.627957 | Preparing job workspace
2025-10-01 00:06:40.633574 | Running Ansible setup...
2025-10-01 00:06:47.077709 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-01 00:06:47.714983 | 
2025-10-01 00:06:47.715117 | PLAY [localhost]
2025-10-01 00:06:47.723905 | 
2025-10-01 00:06:47.723981 | TASK [Gathering Facts]
2025-10-01 00:06:48.844456 | localhost | ok
2025-10-01 00:06:48.868590 | 
2025-10-01 00:06:48.868831 | TASK [Setup log path fact]
2025-10-01 00:06:48.890240 | localhost | ok
2025-10-01 00:06:48.903761 | 
2025-10-01 00:06:48.903883 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-01 00:06:48.931929 | localhost | ok
2025-10-01 00:06:48.939968 | 
2025-10-01 00:06:48.940072 | TASK [emit-job-header : Print job information]
2025-10-01 00:06:48.980062 | # Job Information
2025-10-01 00:06:48.980280 | Ansible Version: 2.15.12
2025-10-01 00:06:48.980324 | Job: ansible-test-sanity-docker-milestone
2025-10-01 00:06:48.980353 | Pipeline: periodic
2025-10-01 00:06:48.980380 | Executor: ze02.softwarefactory-project.io
2025-10-01 00:06:48.980406 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-01 00:06:48.980435 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d19/ansible/d19972ae26484e438cccc095fbff5030/
2025-10-01 00:06:48.980462 | Event ID: 2d247e7dd365484888695175254b0a86
2025-10-01 00:06:48.986085 | 
2025-10-01 00:06:48.986175 | LOOP [emit-job-header : Print node information]
2025-10-01 00:06:49.087886 | localhost | ok:
2025-10-01 00:06:49.088098 | localhost | # Node Information
2025-10-01 00:06:49.088126 | localhost | Inventory Hostname: controller
2025-10-01 00:06:49.088146 | localhost | Hostname: ip-172-16-80-208
2025-10-01 00:06:49.088164 | localhost | Username: zuul-worker
2025-10-01 00:06:49.088184 | localhost | Distro: Fedora 37
2025-10-01 00:06:49.088214 | localhost | Provider: ansible-us-east-2
2025-10-01 00:06:49.088232 | localhost | Region: us-east-2
2025-10-01 00:06:49.088249 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-01 00:06:49.088266 | localhost | Product Name: t3.small
2025-10-01 00:06:49.088283 | localhost | Interface IP: 18.188.178.239
2025-10-01 00:06:49.104995 | 
2025-10-01 00:06:49.105173 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-01 00:06:49.519141 | localhost -> localhost | changed
2025-10-01 00:06:49.525063 | 
2025-10-01 00:06:49.525135 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-01 00:06:50.408163 | localhost -> localhost | changed
2025-10-01 00:06:50.428858 | 
2025-10-01 00:06:50.428920 | PLAY [all:!appliance*]
2025-10-01 00:06:50.444901 | 
2025-10-01 00:06:50.444995 | TASK [include_role : start-zuul-console]
2025-10-01 00:06:50.465022 | controller | ok
2025-10-01 00:06:50.480799 | 
2025-10-01 00:06:50.480921 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-01 00:06:51.188833 | controller | ok
2025-10-01 00:06:51.209526 | 
2025-10-01 00:06:51.209757 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-01 00:06:53.196964 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-01 00:06:53.211745 | 
2025-10-01 00:06:53.211896 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-01 00:06:53.377742 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.395439 | 
2025-10-01 00:06:53.395655 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-01 00:06:53.424575 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.433918 | 
2025-10-01 00:06:53.434028 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-01 00:06:53.461566 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.471143 | 
2025-10-01 00:06:53.471248 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-01 00:06:53.498167 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.506941 | 
2025-10-01 00:06:53.507107 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-01 00:06:53.533657 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.542616 | 
2025-10-01 00:06:53.542734 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-01 00:06:53.569783 | controller | skipping: Conditional result was False
2025-10-01 00:06:53.586863 | 
2025-10-01 00:06:53.586966 | TASK [Disable Fedora Modular]
2025-10-01 00:06:54.361070 | controller | changed
2025-10-01 00:06:54.373386 | 
2025-10-01 00:06:54.373518 | TASK [Enable EPEL]
2025-10-01 00:06:54.400581 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.410092 | 
2025-10-01 00:06:54.410193 | TASK [Register the RHEL node]
2025-10-01 00:06:54.561579 | 
2025-10-01 00:06:54.561834 | TASK [Show the subscription-manager status]
2025-10-01 00:06:54.768805 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.787086 | 
2025-10-01 00:06:54.787210 | TASK [Enable EPEL on RHEL]
2025-10-01 00:06:54.957934 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.974251 | 
2025-10-01 00:06:54.974483 | TASK [Install git and tox]
2025-10-01 00:08:22.050429 | controller | changed
2025-10-01 00:08:22.060622 | 
2025-10-01 00:08:22.060783 | TASK [include_role : prepare-workspace]
2025-10-01 00:08:22.093027 | controller | ok
2025-10-01 00:08:22.116394 | 
2025-10-01 00:08:22.116550 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-01 00:08:22.627203 | controller | ok
2025-10-01 00:08:22.645080 | 
2025-10-01 00:08:22.645335 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-01 00:08:35.568290 | controller | Output suppressed because no_log was given
2025-10-01 00:08:35.578772 | 
2025-10-01 00:08:35.578842 | TASK [include_role : prepare-workspace-openshift]
2025-10-01 00:08:35.606367 | controller | skipping: Conditional result was False
2025-10-01 00:08:35.677443 | 
2025-10-01 00:08:35.677593 | PLAY [all:!appliance]
2025-10-01 00:08:35.697438 | 
2025-10-01 00:08:35.697554 | TASK [Run add-build-sshkey role (RSA)]
2025-10-01 00:08:35.731288 | controller | ok
2025-10-01 00:08:35.751051 | 
2025-10-01 00:08:35.751396 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-01 00:08:36.085520 | controller -> localhost | ok
2025-10-01 00:08:36.096968 | 
2025-10-01 00:08:36.097163 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-01 00:08:36.120364 | controller | ok
2025-10-01 00:08:36.136868 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-01 00:08:36.143559 | 
2025-10-01 00:08:36.143630 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-01 00:08:36.689846 | controller -> localhost | Generating public/private rsa key pair.
2025-10-01 00:08:36.690194 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_rsa.
2025-10-01 00:08:36.690233 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_rsa.pub.
2025-10-01 00:08:36.690258 | controller -> localhost | The key fingerprint is:
2025-10-01 00:08:36.690282 | controller -> localhost | SHA256:kyMDM11QGtluQbo3pQxJ9cXsAXYYs7az5Qt806gMEZc zuul-build-sshkey
2025-10-01 00:08:36.690302 | controller -> localhost | The key's randomart image is:
2025-10-01 00:08:36.690322 | controller -> localhost | +---[RSA 2048]----+
2025-10-01 00:08:36.690340 | controller -> localhost | |      +B= =*o    |
2025-10-01 00:08:36.690359 | controller -> localhost | |     o.*oo.*+    |
2025-10-01 00:08:36.690377 | controller -> localhost | |    + *...E. .   |
2025-10-01 00:08:36.690395 | controller -> localhost | |     + +oB ..    |
2025-10-01 00:08:36.690412 | controller -> localhost | |      +.S o .    |
2025-10-01 00:08:36.690441 | controller -> localhost | |       + * = o   |
2025-10-01 00:08:36.690466 | controller -> localhost | |        . + = .  |
2025-10-01 00:08:36.690486 | controller -> localhost | |         o + o   |
2025-10-01 00:08:36.690504 | controller -> localhost | |          o .    |
2025-10-01 00:08:36.690524 | controller -> localhost | +----[SHA256]-----+
2025-10-01 00:08:36.690581 | controller -> localhost | ok: Runtime: 0:00:00.139216
2025-10-01 00:08:36.698388 | 
2025-10-01 00:08:36.698455 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-01 00:08:36.731492 | controller | ok
2025-10-01 00:08:36.743349 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-01 00:08:36.755184 | 
2025-10-01 00:08:36.755366 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-01 00:08:36.772892 | controller | skipping: Conditional result was False
2025-10-01 00:08:36.781239 | 
2025-10-01 00:08:36.781336 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-01 00:08:37.465567 | controller | changed
2025-10-01 00:08:37.479100 | 
2025-10-01 00:08:37.479269 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-01 00:08:37.828223 | controller | ok
2025-10-01 00:08:37.841267 | 
2025-10-01 00:08:37.841422 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-01 00:08:39.118567 | controller | changed
2025-10-01 00:08:39.133879 | 
2025-10-01 00:08:39.134088 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-01 00:08:40.434228 | controller | changed
2025-10-01 00:08:40.448241 | 
2025-10-01 00:08:40.448443 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-01 00:08:40.478292 | controller | skipping: Conditional result was False
2025-10-01 00:08:40.494739 | 
2025-10-01 00:08:40.495048 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-01 00:08:40.984862 | controller -> localhost | changed
2025-10-01 00:08:41.009301 | 
2025-10-01 00:08:41.009447 | TASK [add-build-sshkey : Add back temp key]
2025-10-01 00:08:41.395819 | controller -> localhost | Identity added: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_rsa (zuul-build-sshkey)
2025-10-01 00:08:41.396122 | controller -> localhost | ok: Runtime: 0:00:00.009766
2025-10-01 00:08:41.403001 | 
2025-10-01 00:08:41.403063 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-01 00:08:41.923610 | controller | ok
2025-10-01 00:08:41.934003 | 
2025-10-01 00:08:41.934146 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-01 00:08:41.972361 | controller | skipping: Conditional result was False
2025-10-01 00:08:41.995794 | 
2025-10-01 00:08:41.995923 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-01 00:08:42.031613 | controller | ok
2025-10-01 00:08:42.056729 | 
2025-10-01 00:08:42.056902 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-01 00:08:42.349651 | controller -> localhost | ok
2025-10-01 00:08:42.365775 | 
2025-10-01 00:08:42.365909 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-01 00:08:42.406012 | controller | ok
2025-10-01 00:08:42.428359 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-01 00:08:42.436766 | 
2025-10-01 00:08:42.436856 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-01 00:08:42.790109 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-01 00:08:42.790452 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_ecdsa.
2025-10-01 00:08:42.790491 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_ecdsa.pub.
2025-10-01 00:08:42.790573 | controller -> localhost | The key fingerprint is:
2025-10-01 00:08:42.790600 | controller -> localhost | SHA256:/4GFRXEh7+0/CdymD9pykUUsgMpYmDWUaZjHOTvxlfI zuul-build-sshkey
2025-10-01 00:08:42.790626 | controller -> localhost | The key's randomart image is:
2025-10-01 00:08:42.790650 | controller -> localhost | +---[ECDSA 521]---+
2025-10-01 00:08:42.790703 | controller -> localhost | |      O++ ..*.+. |
2025-10-01 00:08:42.790730 | controller -> localhost | |     = @.o + = o |
2025-10-01 00:08:42.790754 | controller -> localhost | |      * * + . +  |
2025-10-01 00:08:42.790778 | controller -> localhost | |     . = . E . o |
2025-10-01 00:08:42.790802 | controller -> localhost | |        S . o = .|
2025-10-01 00:08:42.790825 | controller -> localhost | |         . o = + |
2025-10-01 00:08:42.790847 | controller -> localhost | |          o ..= o|
2025-10-01 00:08:42.790870 | controller -> localhost | |           oo+.o.|
2025-10-01 00:08:42.790894 | controller -> localhost | |           .+...o|
2025-10-01 00:08:42.790919 | controller -> localhost | +----[SHA256]-----+
2025-10-01 00:08:42.790999 | controller -> localhost | ok: Runtime: 0:00:00.017699
2025-10-01 00:08:42.800220 | 
2025-10-01 00:08:42.800318 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-01 00:08:42.833304 | controller | ok
2025-10-01 00:08:42.845176 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-01 00:08:42.856985 | 
2025-10-01 00:08:42.857069 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-01 00:08:42.892834 | controller | skipping: Conditional result was False
2025-10-01 00:08:42.899883 | 
2025-10-01 00:08:42.899958 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-01 00:08:43.341446 | controller | changed
2025-10-01 00:08:43.349795 | 
2025-10-01 00:08:43.349886 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-01 00:08:43.708107 | controller | ok
2025-10-01 00:08:43.721164 | 
2025-10-01 00:08:43.721308 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-01 00:08:45.364884 | controller | changed
2025-10-01 00:08:45.373108 | 
2025-10-01 00:08:45.373193 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-01 00:08:46.714156 | controller | changed
2025-10-01 00:08:46.728898 | 
2025-10-01 00:08:46.729107 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-01 00:08:46.756849 | controller | skipping: Conditional result was False
2025-10-01 00:08:46.770856 | 
2025-10-01 00:08:46.771044 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-01 00:08:47.045114 | controller -> localhost | changed
2025-10-01 00:08:47.071108 | 
2025-10-01 00:08:47.071337 | TASK [add-build-sshkey : Add back temp key]
2025-10-01 00:08:47.447145 | controller -> localhost | Identity added: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/d19972ae26484e438cccc095fbff5030_id_ecdsa (zuul-build-sshkey)
2025-10-01 00:08:47.447436 | controller -> localhost | ok: Runtime: 0:00:00.009674
2025-10-01 00:08:47.500879 | 
2025-10-01 00:08:47.501043 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-01 00:08:47.865937 | controller | ok
2025-10-01 00:08:47.890601 | 
2025-10-01 00:08:47.890835 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-01 00:08:47.918868 | controller | skipping: Conditional result was False
2025-10-01 00:08:47.942462 | 
2025-10-01 00:08:47.942594 | TASK [include_role : remove-zuul-sshkey]
2025-10-01 00:08:47.959487 | controller | skipping: Conditional result was False
2025-10-01 00:08:47.970479 | 
2025-10-01 00:08:47.970590 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-01 00:08:48.286220 | controller | ok: "logs"
2025-10-01 00:08:48.286939 | controller | ok: All items complete
2025-10-01 00:08:48.287020 | 
2025-10-01 00:08:48.563259 | controller | ok: "artifacts"
2025-10-01 00:08:48.840052 | controller | ok: "docs"
2025-10-01 00:08:48.859560 | 
2025-10-01 00:08:48.859742 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-01 00:08:49.203905 | controller | changed: "logs"
2025-10-01 00:08:49.489582 | controller | changed: "artifacts"
2025-10-01 00:08:49.777149 | controller | changed: "docs"
2025-10-01 00:08:49.839950 | 
2025-10-01 00:08:49.840125 | PLAY RECAP
2025-10-01 00:08:49.840181 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-01 00:08:49.840222 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-01 00:08:49.840247 | 
2025-10-01 00:08:49.975764 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-01 00:08:49.982415 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-01 00:08:50.726966 | 
2025-10-01 00:08:50.727298 | PLAY [all]
2025-10-01 00:08:50.759806 | 
2025-10-01 00:08:50.760044 | TASK [Install binary dependencies]
2025-10-01 00:08:50.822433 | controller | ok
2025-10-01 00:08:50.847984 | 
2025-10-01 00:08:50.848187 | TASK [bindep : Include find tasks]
2025-10-01 00:08:50.882006 | controller | ok
2025-10-01 00:08:50.893022 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-01 00:08:50.902898 | 
2025-10-01 00:08:50.903066 | TASK [bindep : Look for bindep.txt]
2025-10-01 00:08:51.467414 | controller | ok
2025-10-01 00:08:51.479243 | 
2025-10-01 00:08:51.479439 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:51.507895 | controller | skipping: Conditional result was False
2025-10-01 00:08:51.522582 | 
2025-10-01 00:08:51.522795 | TASK [bindep : Look for other-requirements.txt]
2025-10-01 00:08:51.833179 | controller | ok
2025-10-01 00:08:51.838626 | 
2025-10-01 00:08:51.838718 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:51.874245 | controller | skipping: Conditional result was False
2025-10-01 00:08:51.881092 | 
2025-10-01 00:08:51.881170 | TASK [bindep : Look for bindep fallback file]
2025-10-01 00:08:51.917221 | controller | skipping: Conditional result was False
2025-10-01 00:08:51.927034 | 
2025-10-01 00:08:51.927269 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:51.954169 | controller | skipping: Conditional result was False
2025-10-01 00:08:51.960579 | 
2025-10-01 00:08:51.960650 | TASK [bindep : Include bindep tasks]
2025-10-01 00:08:51.985694 | controller | skipping: Conditional result was False
2025-10-01 00:08:51.994709 | 
2025-10-01 00:08:51.994874 | TASK [bindep : Include install tasks]
2025-10-01 00:08:52.025803 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.035222 | 
2025-10-01 00:08:52.035342 | LOOP [bindep : Include package tasks]
2025-10-01 00:08:52.092727 | 
2025-10-01 00:08:52.092938 | TASK [Run test-setup role]
2025-10-01 00:08:52.113960 | controller | ok
2025-10-01 00:08:52.134607 | 
2025-10-01 00:08:52.134805 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-01 00:08:52.432259 | controller | ok
2025-10-01 00:08:52.447497 | 
2025-10-01 00:08:52.447661 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-01 00:08:52.594921 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.646031 | 
2025-10-01 00:08:52.646111 | PLAY RECAP
2025-10-01 00:08:52.646164 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-01 00:08:52.646192 | 
2025-10-01 00:08:52.789002 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-01 00:08:52.789992 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-01 00:08:53.496909 | 
2025-10-01 00:08:53.497151 | PLAY [controller]
2025-10-01 00:08:53.526529 | 
2025-10-01 00:08:53.526790 | TASK [Create the /root directory]
2025-10-01 00:08:54.285327 | controller | ok
2025-10-01 00:08:54.297490 | 
2025-10-01 00:08:54.297771 | TASK [Install glibc-langpack-en]
2025-10-01 00:09:02.547765 | controller | ok: Nothing to do
2025-10-01 00:09:02.563563 | 
2025-10-01 00:09:02.563811 | TASK [Ensure controller directory exists]
2025-10-01 00:09:03.003835 | controller | changed
2025-10-01 00:09:03.017196 | 
2025-10-01 00:09:03.017346 | TASK [Install container runtime]
2025-10-01 00:09:03.100962 | controller | ok
2025-10-01 00:09:03.163718 | 
2025-10-01 00:09:03.163863 | LOOP [ensure-podman : Find distribution installation]
2025-10-01 00:09:03.226137 | controller | ok: "/var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-01 00:09:03.241577 | controller | included: /var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-01 00:09:03.249090 | 
2025-10-01 00:09:03.249168 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-01 00:10:17.485595 | controller | changed
2025-10-01 00:10:17.503018 | 
2025-10-01 00:10:17.503218 | TASK [ensure-podman : Fetch podman version]
2025-10-01 00:10:18.215530 | controller | Client:       Podman Engine
2025-10-01 00:10:18.242481 | controller | Version:      4.6.2
2025-10-01 00:10:18.242522 | controller | API Version:  4.6.2
2025-10-01 00:10:18.242529 | controller | Go Version:   go1.19.12
2025-10-01 00:10:18.242547 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-01 00:10:18.242554 | controller | OS/Arch:      linux/amd64
2025-10-01 00:10:18.652548 | controller | ok: Runtime: 0:00:00.224785
2025-10-01 00:10:18.665116 | 
2025-10-01 00:10:18.665298 | TASK [ensure-podman : Print podman version installed]
2025-10-01 00:10:18.716591 | Podman version: Client:       Podman Engine
2025-10-01 00:10:18.716981 | Version:      4.6.2
2025-10-01 00:10:18.717072 | API Version:  4.6.2
2025-10-01 00:10:18.717170 | Go Version:   go1.19.12
2025-10-01 00:10:18.717228 | Built:        Mon Aug 28 19:38:31 2023
2025-10-01 00:10:18.717272 | OS/Arch:      linux/amd64
2025-10-01 00:10:18.728722 | 
2025-10-01 00:10:18.728849 | TASK [ensure-podman : Validate podman engine]
2025-10-01 00:10:18.871497 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.878209 | 
2025-10-01 00:10:18.878281 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-01 00:10:18.892789 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.904033 | 
2025-10-01 00:10:18.904110 | TASK [Ensure python3.8 is present]
2025-10-01 00:10:18.918707 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.925222 | 
2025-10-01 00:10:18.925307 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-01 00:10:18.955938 | controller | ok
2025-10-01 00:10:18.977858 | 
2025-10-01 00:10:18.978048 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-01 00:10:22.675155 | controller | ok: Nothing to do
2025-10-01 00:10:22.683752 | 
2025-10-01 00:10:22.683934 | TASK [our-ensure-python : Also install python3-devel]
2025-10-01 00:10:35.639106 | controller | changed
2025-10-01 00:10:35.655894 | 
2025-10-01 00:10:35.656057 | TASK [Run ensure-virtualenv role]
2025-10-01 00:10:35.681551 | controller | ok
2025-10-01 00:10:35.715296 | 
2025-10-01 00:10:35.715433 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-01 00:10:36.105550 | controller | /usr/bin/virtualenv
2025-10-01 00:10:36.382990 | controller | ok: Runtime: 0:00:00.004437
2025-10-01 00:10:36.390965 | 
2025-10-01 00:10:36.391106 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-01 00:10:36.414844 | controller | skipping: Conditional result was False
2025-10-01 00:10:36.415359 | controller | ok: All items complete
2025-10-01 00:10:36.415428 | 
2025-10-01 00:10:36.435026 | 
2025-10-01 00:10:36.435148 | TASK [Find the full path of the Python interpreter]
2025-10-01 00:10:36.863888 | controller | /usr/bin/python3
2025-10-01 00:10:37.067415 | controller | ok
2025-10-01 00:10:37.082092 | 
2025-10-01 00:10:37.082261 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-01 00:10:38.498134 | controller | created virtual environment CPython3.11.0.final.0-64 in 785ms
2025-10-01 00:10:38.547609 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-01 00:10:38.548205 | 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-worker/.local/share/virtualenv)
2025-10-01 00:10:38.548229 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-01 00:10:38.548251 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-01 00:10:38.739981 | controller | changed
2025-10-01 00:10:38.755093 | 
2025-10-01 00:10:38.755257 | TASK [Set selinux package]
2025-10-01 00:10:38.786034 | controller | ok
2025-10-01 00:10:38.798094 | 
2025-10-01 00:10:38.798230 | TASK [Set selinux package (Fedora)]
2025-10-01 00:10:38.841594 | controller | ok
2025-10-01 00:10:38.847233 | 
2025-10-01 00:10:38.847301 | TASK [Install selinux into virtualenv]
2025-10-01 00:10:41.465724 | controller | Collecting selinux-please-lie-to-me
2025-10-01 00:10:41.553191 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-01 00:10:42.078087 | controller | Collecting setuptools<50.0.0
2025-10-01 00:10:42.091231 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-01 00:10:42.226439 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.3 MB/s eta 0:00:00
2025-10-01 00:10:42.380097 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-01 00:10:42.380434 | controller |   Attempting uninstall: setuptools
2025-10-01 00:10:42.385406 | controller |     Found existing installation: setuptools 62.6.0
2025-10-01 00:10:42.499002 | controller |     Uninstalling setuptools-62.6.0:
2025-10-01 00:10:42.514165 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-01 00:10:43.250410 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-01 00:10:43.459327 | controller |
2025-10-01 00:10:43.667765 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-01 00:10:43.667810 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-01 00:10:44.042506 | controller | ok: Runtime: 0:00:04.338799
2025-10-01 00:10:44.058405 | 
2025-10-01 00:10:44.058625 | TASK [Install pytest-forked into virtualenv]
2025-10-01 00:10:45.288428 | controller | Collecting pytest-forked
2025-10-01 00:10:45.374592 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-01 00:10:45.431560 | controller | Collecting py
2025-10-01 00:10:45.444576 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-01 00:10:45.479524 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-10-01 00:10:45.656593 | controller | Collecting pytest>=3.10
2025-10-01 00:10:45.669644 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-01 00:10:45.730451 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-01 00:10:45.785750 | controller | Collecting iniconfig>=1
2025-10-01 00:10:45.799096 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-01 00:10:45.871853 | controller | Collecting packaging>=20
2025-10-01 00:10:45.884741 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-01 00:10:45.896869 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00
2025-10-01 00:10:45.942473 | controller | Collecting pluggy<2,>=1.5
2025-10-01 00:10:45.955248 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-01 00:10:46.029666 | controller | Collecting pygments>=2.7.2
2025-10-01 00:10:46.042455 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-01 00:10:46.168298 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.9 MB/s eta 0:00:00
2025-10-01 00:10:46.299632 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-01 00:10:48.559348 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-01 00:10:48.580956 | controller |
2025-10-01 00:10:48.779058 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-01 00:10:48.779103 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-01 00:10:49.233355 | controller | ok: Runtime: 0:00:04.232971
2025-10-01 00:10:49.247166 | 
2025-10-01 00:10:49.247330 | TASK [Update pip]
2025-10-01 00:10:50.364099 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-01 00:10:50.594520 | controller | Collecting pip
2025-10-01 00:10:50.697657 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-01 00:10:51.035726 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 5.3 MB/s eta 0:00:00
2025-10-01 00:10:51.204049 | controller | Installing collected packages: pip
2025-10-01 00:10:51.205292 | controller |   Attempting uninstall: pip
2025-10-01 00:10:51.210299 | controller |     Found existing installation: pip 22.2.2
2025-10-01 00:10:51.546064 | controller |     Uninstalling pip-22.2.2:
2025-10-01 00:10:51.584986 | controller |       Successfully uninstalled pip-22.2.2
2025-10-01 00:10:53.359113 | controller | Successfully installed pip-25.2
2025-10-01 00:10:53.906516 | controller | ok: Runtime: 0:00:03.795541
2025-10-01 00:10:53.915464 | 
2025-10-01 00:10:53.915556 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-01 00:10:54.422480 | controller | changed
2025-10-01 00:10:54.434926 | 
2025-10-01 00:10:54.435059 | TASK [Install ansible into virtualenv]
2025-10-01 00:10:55.552497 | controller | Processing ./src/github.com/ansible/ansible
2025-10-01 00:10:55.558976 | controller |   Installing build dependencies: started
2025-10-01 00:10:57.446758 | controller |   Installing build dependencies: finished with status 'done'
2025-10-01 00:10:57.447956 | controller |   Getting requirements to build wheel: started
2025-10-01 00:10:58.932227 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-01 00:10:59.853220 | controller |   Preparing metadata (pyproject.toml): started
2025-10-01 00:10:59.853279 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-01 00:10:59.856407 | 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-01 00:10:59.861264 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-01 00:11:00.144851 | controller | ERROR
2025-10-01 00:11:00.145280 | controller | {
2025-10-01 00:11:00.145362 | controller |   "delta": "0:00:05.075589",
2025-10-01 00:11:00.145409 | controller |   "end": "2025-10-01 00:11:00.008044",
2025-10-01 00:11:00.145448 | controller |   "msg": "non-zero return code",
2025-10-01 00:11:00.145505 | controller |   "rc": 1,
2025-10-01 00:11:00.145542 | controller |   "start": "2025-10-01 00:10:54.932455"
2025-10-01 00:11:00.145579 | controller | }
failure
2025-10-01 00:11:00.149345 | 
2025-10-01 00:11:00.149450 | PLAY RECAP
2025-10-01 00:11:00.149544 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-01 00:11:00.149588 | 
2025-10-01 00:11:00.298415 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-01 00:11:00.299423 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-01 00:11:00.929193 | 
2025-10-01 00:11:00.929342 | PLAY [all]
2025-10-01 00:11:00.952612 | 
2025-10-01 00:11:00.952787 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-01 00:11:01.731017 | controller | changed: non-zero return code
2025-10-01 00:11:01.738328 | 
2025-10-01 00:11:01.738468 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-01 00:11:01.763938 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.773353 | 
2025-10-01 00:11:01.773505 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-01 00:11:01.807909 | 
2025-10-01 00:11:01.808116 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-01 00:11:01.831628 | 
2025-10-01 00:11:01.831949 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-01 00:11:01.850533 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.858056 | 
2025-10-01 00:11:01.858173 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-01 00:11:01.883995 | 
2025-10-01 00:11:01.884174 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-01 00:11:01.899814 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.910007 | 
2025-10-01 00:11:01.910182 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-01 00:11:01.937446 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.947345 | 
2025-10-01 00:11:01.947480 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-01 00:11:01.963988 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.992612 | 
2025-10-01 00:11:01.992772 | PLAY RECAP
2025-10-01 00:11:01.992833 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-01 00:11:01.992865 | 
2025-10-01 00:11:02.136805 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-01 00:11:02.137813 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-01 00:11:02.780443 | 
2025-10-01 00:11:02.780580 | PLAY [all:!appliance*]
2025-10-01 00:11:02.816233 | 
2025-10-01 00:11:02.816388 | TASK [unregister the node]
2025-10-01 00:11:02.953852 | controller | skipping: Conditional result was False
2025-10-01 00:11:02.967224 | 
2025-10-01 00:11:02.967415 | TASK [include_role : fetch-output]
2025-10-01 00:11:03.008988 | controller | ok
2025-10-01 00:11:03.039934 | 
2025-10-01 00:11:03.040083 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-01 00:11:03.097284 | controller | skipping: Conditional result was False
2025-10-01 00:11:03.106842 | 
2025-10-01 00:11:03.106979 | TASK [fetch-output : Set log path for single node]
2025-10-01 00:11:03.148828 | controller | ok
2025-10-01 00:11:03.154343 | 
2025-10-01 00:11:03.154415 | LOOP [fetch-output : Ensure local output dirs]
2025-10-01 00:11:03.612181 | controller -> localhost | ok: "/var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/logs"
2025-10-01 00:11:03.850451 | controller -> localhost | changed: "/var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/artifacts"
2025-10-01 00:11:04.087348 | controller -> localhost | changed: "/var/lib/zuul/builds/d19972ae26484e438cccc095fbff5030/work/docs"
2025-10-01 00:11:04.100064 | 
2025-10-01 00:11:04.100168 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-01 00:11:05.373746 | controller | changed:
2025-10-01 00:11:05.374172 | controller | .d..t...... ./
2025-10-01 00:11:05.374280 | controller | cd+++++++++ controller/
2025-10-01 00:11:05.374409 | controller | changed: All items complete
2025-10-01 00:11:05.374467 | 
2025-10-01 00:11:06.482725 | controller | changed: .d..t...... ./
2025-10-01 00:11:07.616900 | controller | changed: .d..t...... ./
2025-10-01 00:11:07.650523 | 
2025-10-01 00:11:07.650725 | TASK [include_role : fetch-output-openshift]
2025-10-01 00:11:07.666906 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.674988 | 
2025-10-01 00:11:07.675114 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-01 00:11:07.720258 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.721065 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.753549 | 
2025-10-01 00:11:07.753708 | PLAY [localhost]
2025-10-01 00:11:07.766006 | 
2025-10-01 00:11:07.766103 | TASK [Run Zuul manifest role]
2025-10-01 00:11:07.794825 | localhost | ok
2025-10-01 00:11:07.815992 | 
2025-10-01 00:11:07.816121 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-01 00:11:08.222556 | localhost | changed
2025-10-01 00:11:08.233353 | 
2025-10-01 00:11:08.233494 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-01 00:11:08.266295 | localhost | ok
2025-10-01 00:11:08.285361 | 
2025-10-01 00:11:08.285542 | TASK [Set zuul-log-path fact]
2025-10-01 00:11:08.308715 | localhost | ok
2025-10-01 00:11:08.322619 | 
2025-10-01 00:11:08.322737 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-01 00:11:08.353539 | localhost | ok
2025-10-01 00:11:08.363317 | 
2025-10-01 00:11:08.363402 | LOOP [Run upload-logs-swift role]
2025-10-01 00:11:08.402406 | localhost | Output suppressed because no_log was given
2025-10-01 00:11:08.429378 | 
2025-10-01 00:11:08.429521 | TASK [Set zuul-log-path fact]
2025-10-01 00:11:08.455449 | localhost | skipping: Conditional result was False
2025-10-01 00:11:08.461436 | 
2025-10-01 00:11:08.461529 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-01 00:11:08.904149 | localhost -> localhost | ok: Runtime: 0:00:00.011319
2025-10-01 00:11:08.917052 | 
2025-10-01 00:11:08.917243 | TASK [upload-logs-swift : Upload logs to swift]