2025-10-27 00:06:42.395127 | Job console starting...
2025-10-27 00:06:42.408808 | Updating repositories
2025-10-27 00:06:42.557835 | Preparing job workspace
2025-10-27 00:06:46.398252 | Running Ansible setup...
2025-10-27 00:06:52.779063 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:06:53.341972 | 
2025-10-27 00:06:53.342083 | PLAY [localhost]
2025-10-27 00:06:53.349993 | 
2025-10-27 00:06:53.350059 | TASK [Gathering Facts]
2025-10-27 00:06:54.384856 | localhost | ok
2025-10-27 00:06:54.412698 | 
2025-10-27 00:06:54.412937 | TASK [Setup log path fact]
2025-10-27 00:06:54.435185 | localhost | ok
2025-10-27 00:06:54.453669 | 
2025-10-27 00:06:54.453834 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:06:54.494628 | localhost | ok
2025-10-27 00:06:54.506445 | 
2025-10-27 00:06:54.506566 | TASK [emit-job-header : Print job information]
2025-10-27 00:06:54.558040 | # Job Information
2025-10-27 00:06:54.558238 | Ansible Version: 2.15.12
2025-10-27 00:06:54.558283 | Job: ansible-test-sanity-docker-milestone
2025-10-27 00:06:54.558313 | Pipeline: periodic
2025-10-27 00:06:54.558339 | Executor: ze03.softwarefactory-project.io
2025-10-27 00:06:54.558365 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-27 00:06:54.558394 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/315/ansible/3157b06e18ee445fbdab02365fc7174f/
2025-10-27 00:06:54.558421 | Event ID: 750469794ad743fdb26497abfe8a4902
2025-10-27 00:06:54.563886 | 
2025-10-27 00:06:54.563977 | LOOP [emit-job-header : Print node information]
2025-10-27 00:06:54.684155 | localhost | ok:
2025-10-27 00:06:54.684377 | localhost | # Node Information
2025-10-27 00:06:54.684404 | localhost | Inventory Hostname: controller
2025-10-27 00:06:54.684424 | localhost | Hostname: ip-172-16-167-148
2025-10-27 00:06:54.684442 | localhost | Username: zuul-worker
2025-10-27 00:06:54.684463 | localhost | Distro: Fedora 37
2025-10-27 00:06:54.684480 | localhost | Provider: ansible-us-east-2
2025-10-27 00:06:54.684498 | localhost | Region: us-east-2
2025-10-27 00:06:54.684514 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-27 00:06:54.684531 | localhost | Product Name: t3.small
2025-10-27 00:06:54.684548 | localhost | Interface IP: 3.145.203.208
2025-10-27 00:06:54.699186 | 
2025-10-27 00:06:54.699293 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-27 00:06:55.102549 | localhost -> localhost | changed
2025-10-27 00:06:55.108295 | 
2025-10-27 00:06:55.108371 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-27 00:06:56.058402 | localhost -> localhost | changed
2025-10-27 00:06:56.100790 | 
2025-10-27 00:06:56.100957 | PLAY [all:!appliance*]
2025-10-27 00:06:56.123594 | 
2025-10-27 00:06:56.123675 | TASK [include_role : start-zuul-console]
2025-10-27 00:06:56.146380 | controller | ok
2025-10-27 00:06:56.160272 | 
2025-10-27 00:06:56.160388 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-27 00:06:56.815858 | controller | ok
2025-10-27 00:06:56.837407 | 
2025-10-27 00:06:56.837571 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-27 00:07:00.208221 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-27 00:07:00.217415 | 
2025-10-27 00:07:00.217514 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-27 00:07:00.552416 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.562168 | 
2025-10-27 00:07:00.562303 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-27 00:07:00.588525 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.605221 | 
2025-10-27 00:07:00.605519 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-27 00:07:00.633425 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.647023 | 
2025-10-27 00:07:00.647165 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-27 00:07:00.686025 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.701947 | 
2025-10-27 00:07:00.702091 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-27 00:07:00.732047 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.745933 | 
2025-10-27 00:07:00.746113 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-27 00:07:00.774000 | controller | skipping: Conditional result was False
2025-10-27 00:07:00.798675 | 
2025-10-27 00:07:00.798850 | TASK [Disable Fedora Modular]
2025-10-27 00:07:01.544044 | controller | changed
2025-10-27 00:07:01.551622 | 
2025-10-27 00:07:01.551704 | TASK [Enable EPEL]
2025-10-27 00:07:01.567519 | controller | skipping: Conditional result was False
2025-10-27 00:07:01.577528 | 
2025-10-27 00:07:01.577619 | TASK [Register the RHEL node]
2025-10-27 00:07:01.747675 | 
2025-10-27 00:07:01.747968 | TASK [Show the subscription-manager status]
2025-10-27 00:07:01.945899 | controller | skipping: Conditional result was False
2025-10-27 00:07:01.958274 | 
2025-10-27 00:07:01.958408 | TASK [Enable EPEL on RHEL]
2025-10-27 00:07:02.119282 | controller | skipping: Conditional result was False
2025-10-27 00:07:02.131598 | 
2025-10-27 00:07:02.131767 | TASK [Install git and tox]
2025-10-27 00:08:44.406288 | controller | changed
2025-10-27 00:08:44.415196 | 
2025-10-27 00:08:44.415311 | TASK [include_role : prepare-workspace]
2025-10-27 00:08:44.448453 | controller | ok
2025-10-27 00:08:44.472617 | 
2025-10-27 00:08:44.472750 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-27 00:08:45.096909 | controller | ok
2025-10-27 00:08:45.109130 | 
2025-10-27 00:08:45.109238 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-27 00:08:58.626118 | controller | Output suppressed because no_log was given
2025-10-27 00:08:58.637353 | 
2025-10-27 00:08:58.637430 | TASK [include_role : prepare-workspace-openshift]
2025-10-27 00:08:58.662223 | controller | skipping: Conditional result was False
2025-10-27 00:08:58.686839 | 
2025-10-27 00:08:58.686915 | PLAY [all:!appliance]
2025-10-27 00:08:58.703470 | 
2025-10-27 00:08:58.703530 | TASK [Run add-build-sshkey role (RSA)]
2025-10-27 00:08:58.733359 | controller | ok
2025-10-27 00:08:58.747554 | 
2025-10-27 00:08:58.747616 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:08:59.057801 | controller -> localhost | ok
2025-10-27 00:08:59.065564 | 
2025-10-27 00:08:59.065638 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:08:59.191540 | controller | ok
2025-10-27 00:08:59.205985 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:08:59.211452 | 
2025-10-27 00:08:59.211513 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:08:59.816885 | controller -> localhost | Generating public/private rsa key pair.
2025-10-27 00:08:59.817307 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_rsa.
2025-10-27 00:08:59.817374 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_rsa.pub.
2025-10-27 00:08:59.817421 | controller -> localhost | The key fingerprint is:
2025-10-27 00:08:59.817466 | controller -> localhost | SHA256:QrsrrtGlZHwm/AVwhbOMIym+UQh5tgNdlT7IxmttNBg zuul-build-sshkey
2025-10-27 00:08:59.817510 | controller -> localhost | The key's randomart image is:
2025-10-27 00:08:59.817553 | controller -> localhost | +---[RSA 2048]----+
2025-10-27 00:08:59.817594 | controller -> localhost | | o .o.o+.        |
2025-10-27 00:08:59.817639 | controller -> localhost | |+ + Eo+          |
2025-10-27 00:08:59.817679 | controller -> localhost | |.+.= Boo         |
2025-10-27 00:08:59.817719 | controller -> localhost | |..=+O.Bo         |
2025-10-27 00:08:59.817804 | controller -> localhost | |...+*=*oS        |
2025-10-27 00:08:59.817863 | controller -> localhost | | o +oBo+         |
2025-10-27 00:08:59.817914 | controller -> localhost | |  +.o.o          |
2025-10-27 00:08:59.817959 | controller -> localhost | | . ..  .         |
2025-10-27 00:08:59.818003 | controller -> localhost | |  .o...          |
2025-10-27 00:08:59.818054 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:08:59.818174 | controller -> localhost | ok: Runtime: 0:00:00.183165
2025-10-27 00:08:59.836321 | 
2025-10-27 00:08:59.836503 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:08:59.880496 | controller | ok
2025-10-27 00:08:59.902224 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:08:59.914720 | 
2025-10-27 00:08:59.914864 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:08:59.941557 | controller | skipping: Conditional result was False
2025-10-27 00:08:59.951585 | 
2025-10-27 00:08:59.951708 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:09:00.928809 | controller | changed
2025-10-27 00:09:00.943139 | 
2025-10-27 00:09:00.943274 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:09:01.727867 | controller | ok
2025-10-27 00:09:01.740402 | 
2025-10-27 00:09:01.740565 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:09:04.776023 | controller | changed
2025-10-27 00:09:04.788751 | 
2025-10-27 00:09:04.788923 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:09:06.377451 | controller | changed
2025-10-27 00:09:06.391119 | 
2025-10-27 00:09:06.391269 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:09:06.409666 | controller | skipping: Conditional result was False
2025-10-27 00:09:06.429006 | 
2025-10-27 00:09:06.429253 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:09:06.856969 | controller -> localhost | changed
2025-10-27 00:09:06.868228 | 
2025-10-27 00:09:06.868311 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:09:07.159795 | controller -> localhost | Identity added: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_rsa (zuul-build-sshkey)
2025-10-27 00:09:07.160241 | controller -> localhost | ok: Runtime: 0:00:00.007546
2025-10-27 00:09:07.177252 | 
2025-10-27 00:09:07.177408 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:09:07.707763 | controller | ok
2025-10-27 00:09:07.720923 | 
2025-10-27 00:09:07.721082 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:09:07.760778 | controller | skipping: Conditional result was False
2025-10-27 00:09:07.785472 | 
2025-10-27 00:09:07.785653 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-27 00:09:07.825060 | controller | ok
2025-10-27 00:09:07.855438 | 
2025-10-27 00:09:07.855559 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:09:08.125592 | controller -> localhost | ok
2025-10-27 00:09:08.139099 | 
2025-10-27 00:09:08.139251 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:09:08.178893 | controller | ok
2025-10-27 00:09:08.201217 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:09:08.209518 | 
2025-10-27 00:09:08.209611 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:09:08.499275 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-27 00:09:08.499493 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_ecdsa.
2025-10-27 00:09:08.499522 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_ecdsa.pub.
2025-10-27 00:09:08.499549 | controller -> localhost | The key fingerprint is:
2025-10-27 00:09:08.499569 | controller -> localhost | SHA256:ZU29jMKjV8XN7JcJ7XvLHCe6bY20tW+S5IUI+0p0Dt0 zuul-build-sshkey
2025-10-27 00:09:08.499588 | controller -> localhost | The key's randomart image is:
2025-10-27 00:09:08.499606 | controller -> localhost | +---[ECDSA 521]---+
2025-10-27 00:09:08.499623 | controller -> localhost | |            .o.+ |
2025-10-27 00:09:08.499641 | controller -> localhost | |           o .+.+|
2025-10-27 00:09:08.499657 | controller -> localhost | |         .o .+ooo|
2025-10-27 00:09:08.499674 | controller -> localhost | |         o=.o.o+o|
2025-10-27 00:09:08.499691 | controller -> localhost | |        S.o*o.E.o|
2025-10-27 00:09:08.499708 | controller -> localhost | |        ..o+. =o=|
2025-10-27 00:09:08.499744 | controller -> localhost | |         ....=oO*|
2025-10-27 00:09:08.499774 | controller -> localhost | |         .  o.B=o|
2025-10-27 00:09:08.499793 | controller -> localhost | |          ...o.oo|
2025-10-27 00:09:08.499810 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:09:08.499858 | controller -> localhost | ok: Runtime: 0:00:00.007630
2025-10-27 00:09:08.507165 | 
2025-10-27 00:09:08.507229 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:09:08.527967 | controller | ok
2025-10-27 00:09:08.534946 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:09:08.543267 | 
2025-10-27 00:09:08.543326 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:09:08.557095 | controller | skipping: Conditional result was False
2025-10-27 00:09:08.563851 | 
2025-10-27 00:09:08.563919 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:09:09.057791 | controller | changed
2025-10-27 00:09:09.072319 | 
2025-10-27 00:09:09.072507 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:09:09.439885 | controller | ok
2025-10-27 00:09:09.454257 | 
2025-10-27 00:09:09.454421 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:09:11.177794 | controller | changed
2025-10-27 00:09:11.190815 | 
2025-10-27 00:09:11.190949 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:09:12.567536 | controller | changed
2025-10-27 00:09:12.581288 | 
2025-10-27 00:09:12.581439 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:09:12.609215 | controller | skipping: Conditional result was False
2025-10-27 00:09:12.624401 | 
2025-10-27 00:09:12.624548 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:09:12.911346 | controller -> localhost | changed
2025-10-27 00:09:12.922572 | 
2025-10-27 00:09:12.922660 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:09:13.190749 | controller -> localhost | Identity added: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/3157b06e18ee445fbdab02365fc7174f_id_ecdsa (zuul-build-sshkey)
2025-10-27 00:09:13.191064 | controller -> localhost | ok: Runtime: 0:00:00.012809
2025-10-27 00:09:13.197912 | 
2025-10-27 00:09:13.197986 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:09:13.612445 | controller | ok
2025-10-27 00:09:13.625366 | 
2025-10-27 00:09:13.625526 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:09:13.654208 | controller | skipping: Conditional result was False
2025-10-27 00:09:13.724547 | 
2025-10-27 00:09:13.724672 | TASK [include_role : remove-zuul-sshkey]
2025-10-27 00:09:13.748790 | controller | skipping: Conditional result was False
2025-10-27 00:09:13.756047 | 
2025-10-27 00:09:13.756171 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-27 00:09:14.157862 | controller | ok: "logs"
2025-10-27 00:09:14.163148 | controller | ok: All items complete
2025-10-27 00:09:14.163246 | 
2025-10-27 00:09:14.514094 | controller | ok: "artifacts"
2025-10-27 00:09:14.840950 | controller | ok: "docs"
2025-10-27 00:09:14.858251 | 
2025-10-27 00:09:14.858448 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-27 00:09:15.359685 | controller | changed: "logs"
2025-10-27 00:09:15.680334 | controller | changed: "artifacts"
2025-10-27 00:09:16.010530 | controller | changed: "docs"
2025-10-27 00:09:16.055314 | 
2025-10-27 00:09:16.055426 | PLAY RECAP
2025-10-27 00:09:16.055469 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-27 00:09:16.055494 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-27 00:09:16.055511 | 
2025-10-27 00:09:16.185991 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:09:16.187683 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:09:16.760550 | 
2025-10-27 00:09:16.760672 | PLAY [all]
2025-10-27 00:09:16.782192 | 
2025-10-27 00:09:16.782277 | TASK [Install binary dependencies]
2025-10-27 00:09:16.832387 | controller | ok
2025-10-27 00:09:16.851668 | 
2025-10-27 00:09:16.851776 | TASK [bindep : Include find tasks]
2025-10-27 00:09:16.880453 | controller | ok
2025-10-27 00:09:16.887652 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-27 00:09:16.893875 | 
2025-10-27 00:09:16.893936 | TASK [bindep : Look for bindep.txt]
2025-10-27 00:09:17.421669 | controller | ok
2025-10-27 00:09:17.429452 | 
2025-10-27 00:09:17.429598 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:17.456114 | controller | skipping: Conditional result was False
2025-10-27 00:09:17.469273 | 
2025-10-27 00:09:17.469438 | TASK [bindep : Look for other-requirements.txt]
2025-10-27 00:09:17.808260 | controller | ok
2025-10-27 00:09:17.815241 | 
2025-10-27 00:09:17.815329 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:17.850847 | controller | skipping: Conditional result was False
2025-10-27 00:09:17.858751 | 
2025-10-27 00:09:17.858846 | TASK [bindep : Look for bindep fallback file]
2025-10-27 00:09:17.905104 | controller | skipping: Conditional result was False
2025-10-27 00:09:17.918562 | 
2025-10-27 00:09:17.918777 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:09:17.955604 | controller | skipping: Conditional result was False
2025-10-27 00:09:17.964056 | 
2025-10-27 00:09:17.964153 | TASK [bindep : Include bindep tasks]
2025-10-27 00:09:18.009970 | controller | skipping: Conditional result was False
2025-10-27 00:09:18.025665 | 
2025-10-27 00:09:18.025855 | TASK [bindep : Include install tasks]
2025-10-27 00:09:18.072602 | controller | skipping: Conditional result was False
2025-10-27 00:09:18.085605 | 
2025-10-27 00:09:18.085801 | LOOP [bindep : Include package tasks]
2025-10-27 00:09:18.176382 | 
2025-10-27 00:09:18.176666 | TASK [Run test-setup role]
2025-10-27 00:09:18.203965 | controller | ok
2025-10-27 00:09:18.234793 | 
2025-10-27 00:09:18.234889 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-27 00:09:18.622543 | controller | ok
2025-10-27 00:09:18.630105 | 
2025-10-27 00:09:18.630189 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-27 00:09:18.766617 | controller | skipping: Conditional result was False
2025-10-27 00:09:18.816167 | 
2025-10-27 00:09:18.816276 | PLAY RECAP
2025-10-27 00:09:18.816331 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:09:18.816365 | 
2025-10-27 00:09:18.912468 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:09:18.914158 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:09:19.499224 | 
2025-10-27 00:09:19.499342 | PLAY [controller]
2025-10-27 00:09:19.518473 | 
2025-10-27 00:09:19.518548 | TASK [Create the /root directory]
2025-10-27 00:09:20.248793 | controller | ok
2025-10-27 00:09:20.259815 | 
2025-10-27 00:09:20.259912 | TASK [Install glibc-langpack-en]
2025-10-27 00:09:28.410456 | controller | ok: Nothing to do
2025-10-27 00:09:28.424127 | 
2025-10-27 00:09:28.424290 | TASK [Ensure controller directory exists]
2025-10-27 00:09:28.909598 | controller | changed
2025-10-27 00:09:28.917530 | 
2025-10-27 00:09:28.917638 | TASK [Install container runtime]
2025-10-27 00:09:28.968814 | controller | ok
2025-10-27 00:09:29.003860 | 
2025-10-27 00:09:29.003977 | LOOP [ensure-podman : Find distribution installation]
2025-10-27 00:09:29.029026 | controller | ok: "/var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-27 00:09:29.045891 | controller | included: /var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-27 00:09:29.052031 | 
2025-10-27 00:09:29.052102 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-27 00:10:56.427631 | controller | changed
2025-10-27 00:10:56.434149 | 
2025-10-27 00:10:56.434235 | TASK [ensure-podman : Fetch podman version]
2025-10-27 00:10:57.371233 | controller | Client:       Podman Engine
2025-10-27 00:10:57.371337 | controller | Version:      4.6.2
2025-10-27 00:10:57.371369 | controller | API Version:  4.6.2
2025-10-27 00:10:57.371396 | controller | Go Version:   go1.19.12
2025-10-27 00:10:57.371434 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:10:57.371462 | controller | OS/Arch:      linux/amd64
2025-10-27 00:10:57.577700 | controller | ok: Runtime: 0:00:00.265734
2025-10-27 00:10:57.586060 | 
2025-10-27 00:10:57.586139 | TASK [ensure-podman : Print podman version installed]
2025-10-27 00:10:57.618895 | Podman version: Client:       Podman Engine
2025-10-27 00:10:57.619072 | Version:      4.6.2
2025-10-27 00:10:57.619100 | API Version:  4.6.2
2025-10-27 00:10:57.619119 | Go Version:   go1.19.12
2025-10-27 00:10:57.619137 | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:10:57.619154 | OS/Arch:      linux/amd64
2025-10-27 00:10:57.625199 | 
2025-10-27 00:10:57.625281 | TASK [ensure-podman : Validate podman engine]
2025-10-27 00:10:57.770032 | controller | skipping: Conditional result was False
2025-10-27 00:10:57.777954 | 
2025-10-27 00:10:57.778042 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-27 00:10:57.803125 | controller | skipping: Conditional result was False
2025-10-27 00:10:57.817618 | 
2025-10-27 00:10:57.817806 | TASK [Ensure python3.8 is present]
2025-10-27 00:10:57.844471 | controller | skipping: Conditional result was False
2025-10-27 00:10:57.852622 | 
2025-10-27 00:10:57.852716 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-27 00:10:57.874389 | controller | ok
2025-10-27 00:10:57.896447 | 
2025-10-27 00:10:57.896628 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-27 00:11:01.904676 | controller | ok: Nothing to do
2025-10-27 00:11:01.910398 | 
2025-10-27 00:11:01.910464 | TASK [our-ensure-python : Also install python3-devel]
2025-10-27 00:11:16.488660 | controller | changed
2025-10-27 00:11:16.517474 | 
2025-10-27 00:11:16.517666 | TASK [Run ensure-virtualenv role]
2025-10-27 00:11:16.543415 | controller | ok
2025-10-27 00:11:16.571945 | 
2025-10-27 00:11:16.572070 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-27 00:11:17.054767 | controller | /usr/bin/virtualenv
2025-10-27 00:11:17.219123 | controller | ok: Runtime: 0:00:00.005337
2025-10-27 00:11:17.233353 | 
2025-10-27 00:11:17.233505 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-27 00:11:17.256919 | controller | skipping: Conditional result was False
2025-10-27 00:11:17.257405 | controller | ok: All items complete
2025-10-27 00:11:17.257477 | 
2025-10-27 00:11:17.322788 | 
2025-10-27 00:11:17.322965 | TASK [Find the full path of the Python interpreter]
2025-10-27 00:11:17.773829 | controller | /usr/bin/python3
2025-10-27 00:11:17.974417 | controller | ok
2025-10-27 00:11:17.987568 | 
2025-10-27 00:11:17.987766 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-27 00:11:19.545004 | controller | created virtual environment CPython3.11.0.final.0-64 in 799ms
2025-10-27 00:11:19.607643 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-27 00:11:19.607695 | 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-27 00:11:19.607710 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-27 00:11:19.607743 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-27 00:11:19.691933 | controller | changed
2025-10-27 00:11:19.704887 | 
2025-10-27 00:11:19.705040 | TASK [Set selinux package]
2025-10-27 00:11:19.744791 | controller | ok
2025-10-27 00:11:19.756091 | 
2025-10-27 00:11:19.756222 | TASK [Set selinux package (Fedora)]
2025-10-27 00:11:19.816859 | controller | ok
2025-10-27 00:11:19.831381 | 
2025-10-27 00:11:19.831794 | TASK [Install selinux into virtualenv]
2025-10-27 00:11:22.526290 | controller | Collecting selinux-please-lie-to-me
2025-10-27 00:11:22.619400 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-27 00:11:23.156955 | controller | Collecting setuptools<50.0.0
2025-10-27 00:11:23.173083 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-27 00:11:23.296505 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.0 MB/s eta 0:00:00
2025-10-27 00:11:23.450752 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-27 00:11:23.451168 | controller |   Attempting uninstall: setuptools
2025-10-27 00:11:23.456197 | controller |     Found existing installation: setuptools 62.6.0
2025-10-27 00:11:23.564180 | controller |     Uninstalling setuptools-62.6.0:
2025-10-27 00:11:23.579864 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-27 00:11:24.337025 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-27 00:11:24.548398 | controller |
2025-10-27 00:11:24.773041 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:11:24.773096 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:11:25.084585 | controller | ok: Runtime: 0:00:04.438148
2025-10-27 00:11:25.099427 | 
2025-10-27 00:11:25.099560 | TASK [Install pytest-forked into virtualenv]
2025-10-27 00:11:26.364948 | controller | Collecting pytest-forked
2025-10-27 00:11:26.451419 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-27 00:11:26.510484 | controller | Collecting py
2025-10-27 00:11:26.523203 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-27 00:11:26.560004 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00
2025-10-27 00:11:26.736053 | controller | Collecting pytest>=3.10
2025-10-27 00:11:26.749528 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-27 00:11:26.810340 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-27 00:11:26.866519 | controller | Collecting iniconfig>=1
2025-10-27 00:11:26.878519 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-27 00:11:26.946560 | controller | Collecting packaging>=20
2025-10-27 00:11:26.958207 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-27 00:11:26.974077 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.3 MB/s eta 0:00:00
2025-10-27 00:11:27.019014 | controller | Collecting pluggy<2,>=1.5
2025-10-27 00:11:27.031275 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-27 00:11:27.109070 | controller | Collecting pygments>=2.7.2
2025-10-27 00:11:27.121417 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-27 00:11:27.242251 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.4 MB/s eta 0:00:00
2025-10-27 00:11:27.379650 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-27 00:11:29.714605 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-27 00:11:29.731001 | controller |
2025-10-27 00:11:29.922554 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:11:29.922608 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:11:30.286489 | controller | ok: Runtime: 0:00:04.311635
2025-10-27 00:11:30.302041 | 
2025-10-27 00:11:30.302188 | TASK [Update pip]
2025-10-27 00:11:31.541022 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-27 00:11:31.826745 | controller | Collecting pip
2025-10-27 00:11:31.921899 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-27 00:11:32.088195 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.0 MB/s eta 0:00:00
2025-10-27 00:11:32.243584 | controller | Installing collected packages: pip
2025-10-27 00:11:32.244031 | controller |   Attempting uninstall: pip
2025-10-27 00:11:32.248606 | controller |     Found existing installation: pip 22.2.2
2025-10-27 00:11:32.513911 | controller |     Uninstalling pip-22.2.2:
2025-10-27 00:11:32.543323 | controller |       Successfully uninstalled pip-22.2.2
2025-10-27 00:11:34.214010 | controller | Successfully installed pip-25.3
2025-10-27 00:11:34.980562 | controller | ok: Runtime: 0:00:03.562536
2025-10-27 00:11:34.991462 | 
2025-10-27 00:11:34.991600 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-27 00:11:35.530503 | controller | changed
2025-10-27 00:11:35.542286 | 
2025-10-27 00:11:35.542427 | TASK [Install ansible into virtualenv]
2025-10-27 00:11:36.679631 | controller | Processing ./src/github.com/ansible/ansible
2025-10-27 00:11:36.686297 | controller |   Installing build dependencies: started
2025-10-27 00:11:38.774596 | controller |   Installing build dependencies: finished with status 'done'
2025-10-27 00:11:40.350718 | controller |   Getting requirements to build wheel: started
2025-10-27 00:11:40.350779 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-27 00:11:40.351281 | controller |   Preparing metadata (pyproject.toml): started
2025-10-27 00:11:41.305341 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-27 00:11:41.307479 | 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-27 00:11:41.312571 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-27 00:11:41.721540 | controller | ERROR
2025-10-27 00:11:41.722047 | controller | {
2025-10-27 00:11:41.722091 | controller |   "delta": "0:00:05.394246",
2025-10-27 00:11:41.722116 | controller |   "end": "2025-10-27 00:11:41.467854",
2025-10-27 00:11:41.722142 | controller |   "msg": "non-zero return code",
2025-10-27 00:11:41.722182 | controller |   "rc": 1,
2025-10-27 00:11:41.722207 | controller |   "start": "2025-10-27 00:11:36.073608"
2025-10-27 00:11:41.722230 | controller | }
failure
2025-10-27 00:11:41.724902 | 
2025-10-27 00:11:41.724965 | PLAY RECAP
2025-10-27 00:11:41.725024 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-27 00:11:41.725051 | 
2025-10-27 00:11:41.856902 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:11:41.858827 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:11:42.466990 | 
2025-10-27 00:11:42.467128 | PLAY [all]
2025-10-27 00:11:42.489952 | 
2025-10-27 00:11:42.490091 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-27 00:11:43.336694 | controller | changed: non-zero return code
2025-10-27 00:11:43.350035 | 
2025-10-27 00:11:43.350285 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-27 00:11:43.377175 | controller | skipping: Conditional result was False
2025-10-27 00:11:43.388188 | 
2025-10-27 00:11:43.388333 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-27 00:11:43.426034 | 
2025-10-27 00:11:43.426287 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-27 00:11:43.458900 | 
2025-10-27 00:11:43.459065 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-27 00:11:43.473200 | controller | skipping: Conditional result was False
2025-10-27 00:11:43.479705 | 
2025-10-27 00:11:43.479815 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-27 00:11:43.510593 | 
2025-10-27 00:11:43.510756 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-27 00:11:43.524544 | controller | skipping: Conditional result was False
2025-10-27 00:11:43.530849 | 
2025-10-27 00:11:43.530930 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-27 00:11:43.549815 | controller | skipping: Conditional result was False
2025-10-27 00:11:43.556189 | 
2025-10-27 00:11:43.556264 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-27 00:11:43.584945 | controller | skipping: Conditional result was False
2025-10-27 00:11:43.609254 | 
2025-10-27 00:11:43.609307 | PLAY RECAP
2025-10-27 00:11:43.609348 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:11:43.609367 | 
2025-10-27 00:11:43.694185 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:11:43.696056 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-27 00:11:44.249618 | 
2025-10-27 00:11:44.249719 | PLAY [all:!appliance*]
2025-10-27 00:11:44.269907 | 
2025-10-27 00:11:44.270020 | TASK [unregister the node]
2025-10-27 00:11:44.412617 | controller | skipping: Conditional result was False
2025-10-27 00:11:44.418425 | 
2025-10-27 00:11:44.418519 | TASK [include_role : fetch-output]
2025-10-27 00:11:44.457673 | controller | ok
2025-10-27 00:11:44.477555 | 
2025-10-27 00:11:44.477660 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-27 00:11:44.542888 | controller | skipping: Conditional result was False
2025-10-27 00:11:44.548859 | 
2025-10-27 00:11:44.548938 | TASK [fetch-output : Set log path for single node]
2025-10-27 00:11:44.607797 | controller | ok
2025-10-27 00:11:44.613091 | 
2025-10-27 00:11:44.613155 | LOOP [fetch-output : Ensure local output dirs]
2025-10-27 00:11:45.011194 | controller -> localhost | ok: "/var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/logs"
2025-10-27 00:11:45.275909 | controller -> localhost | changed: "/var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/artifacts"
2025-10-27 00:11:45.548188 | controller -> localhost | changed: "/var/lib/zuul/builds/3157b06e18ee445fbdab02365fc7174f/work/docs"
2025-10-27 00:11:45.562158 | 
2025-10-27 00:11:45.562258 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-27 00:11:46.848785 | controller | changed:
2025-10-27 00:11:46.849285 | controller | .d..t...... ./
2025-10-27 00:11:46.849325 | controller | cd+++++++++ controller/
2025-10-27 00:11:46.849364 | controller | changed: All items complete
2025-10-27 00:11:46.849386 | 
2025-10-27 00:11:47.945883 | controller | changed: .d..t...... ./
2025-10-27 00:11:48.977861 | controller | changed: .d..t...... ./
2025-10-27 00:11:49.014691 | 
2025-10-27 00:11:49.015000 | TASK [include_role : fetch-output-openshift]
2025-10-27 00:11:49.040708 | controller | skipping: Conditional result was False
2025-10-27 00:11:49.077526 | 
2025-10-27 00:11:49.077891 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-27 00:11:49.126502 | controller | skipping: Conditional result was False
2025-10-27 00:11:49.140992 | controller | skipping: Conditional result was False
2025-10-27 00:11:49.203173 | 
2025-10-27 00:11:49.203296 | PLAY [localhost]
2025-10-27 00:11:49.223164 | 
2025-10-27 00:11:49.223293 | TASK [Run Zuul manifest role]
2025-10-27 00:11:49.245464 | localhost | ok
2025-10-27 00:11:49.266333 | 
2025-10-27 00:11:49.266470 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-27 00:11:49.694442 | localhost | changed
2025-10-27 00:11:49.699213 | 
2025-10-27 00:11:49.699284 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-27 00:11:49.748344 | localhost | ok
2025-10-27 00:11:49.756960 | 
2025-10-27 00:11:49.757065 | TASK [Set zuul-log-path fact]
2025-10-27 00:11:49.774982 | localhost | ok
2025-10-27 00:11:49.788842 | 
2025-10-27 00:11:49.788934 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:11:49.817685 | localhost | ok
2025-10-27 00:11:49.828246 | 
2025-10-27 00:11:49.828350 | LOOP [Run upload-logs-swift role]
2025-10-27 00:11:49.852616 | localhost | Output suppressed because no_log was given
2025-10-27 00:11:49.879054 | 
2025-10-27 00:11:49.879174 | TASK [Set zuul-log-path fact]
2025-10-27 00:11:49.924119 | localhost | skipping: Conditional result was False
2025-10-27 00:11:49.929600 | 
2025-10-27 00:11:49.929675 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-27 00:11:50.412180 | localhost -> localhost | ok: Runtime: 0:00:00.009081
2025-10-27 00:11:50.422673 | 
2025-10-27 00:11:50.422827 | TASK [upload-logs-swift : Upload logs to swift]