2025-09-26 00:17:18.152965 | Job console starting...
2025-09-26 00:17:18.164420 | Updating repositories
2025-09-26 00:17:18.301245 | Preparing job workspace
2025-09-26 00:17:33.285726 | Running Ansible setup...
2025-09-26 00:17:39.882395 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-26 00:17:40.469823 | 
2025-09-26 00:17:40.469935 | PLAY [localhost]
2025-09-26 00:17:40.477969 | 
2025-09-26 00:17:40.478036 | TASK [Gathering Facts]
2025-09-26 00:17:41.537665 | localhost | ok
2025-09-26 00:17:41.560848 | 
2025-09-26 00:17:41.561153 | TASK [Setup log path fact]
2025-09-26 00:17:41.582654 | localhost | ok
2025-09-26 00:17:41.601200 | 
2025-09-26 00:17:41.601343 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-26 00:17:41.631988 | localhost | ok
2025-09-26 00:17:41.644427 | 
2025-09-26 00:17:41.644529 | TASK [emit-job-header : Print job information]
2025-09-26 00:17:41.706259 | # Job Information
2025-09-26 00:17:41.706441 | Ansible Version: 2.15.12
2025-09-26 00:17:41.706484 | Job: ansible-test-sanity-docker-milestone
2025-09-26 00:17:41.706513 | Pipeline: periodic
2025-09-26 00:17:41.706538 | Executor: ze04.softwarefactory-project.io
2025-09-26 00:17:41.706562 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-26 00:17:41.706590 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/259/ansible/259735b00fdc4cdaada37ca27991025d/
2025-09-26 00:17:41.706617 | Event ID: 5696abddc46a4c7696f30c6b91218f52
2025-09-26 00:17:41.712184 | 
2025-09-26 00:17:41.712299 | LOOP [emit-job-header : Print node information]
2025-09-26 00:17:41.911140 | localhost | ok:
2025-09-26 00:17:41.911447 | localhost | # Node Information
2025-09-26 00:17:41.911487 | localhost | Inventory Hostname: controller
2025-09-26 00:17:41.911513 | localhost | Hostname: ip-172-16-28-52
2025-09-26 00:17:41.911539 | localhost | Username: zuul-worker
2025-09-26 00:17:41.911566 | localhost | Distro: Fedora 37
2025-09-26 00:17:41.911591 | localhost | Provider: ansible-us-east-2
2025-09-26 00:17:41.911614 | localhost | Region: us-east-2
2025-09-26 00:17:41.911637 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-26 00:17:41.911660 | localhost | Product Name: t3.small
2025-09-26 00:17:41.911722 | localhost | Interface IP: 18.224.141.92
2025-09-26 00:17:41.931126 | 
2025-09-26 00:17:41.931321 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-26 00:17:42.355964 | localhost -> localhost | changed
2025-09-26 00:17:42.363784 | 
2025-09-26 00:17:42.363897 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-26 00:17:43.233036 | localhost -> localhost | changed
2025-09-26 00:17:43.251957 | 
2025-09-26 00:17:43.252058 | PLAY [all:!appliance*]
2025-09-26 00:17:43.266807 | 
2025-09-26 00:17:43.266873 | TASK [include_role : start-zuul-console]
2025-09-26 00:17:43.285340 | controller | ok
2025-09-26 00:17:43.298267 | 
2025-09-26 00:17:43.298333 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-26 00:17:43.971502 | controller | ok
2025-09-26 00:17:43.995007 | 
2025-09-26 00:17:43.995226 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-26 00:17:45.599178 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-26 00:17:45.607715 | 
2025-09-26 00:17:45.607824 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-26 00:17:45.746211 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.754361 | 
2025-09-26 00:17:45.754448 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-26 00:17:45.778600 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.789779 | 
2025-09-26 00:17:45.789894 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-26 00:17:45.806460 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.814632 | 
2025-09-26 00:17:45.814744 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-26 00:17:45.828090 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.843929 | 
2025-09-26 00:17:45.844057 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-26 00:17:45.858984 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.865148 | 
2025-09-26 00:17:45.865214 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-26 00:17:45.878849 | controller | skipping: Conditional result was False
2025-09-26 00:17:45.890465 | 
2025-09-26 00:17:45.890531 | TASK [Disable Fedora Modular]
2025-09-26 00:17:46.630785 | controller | changed
2025-09-26 00:17:46.643925 | 
2025-09-26 00:17:46.644076 | TASK [Enable EPEL]
2025-09-26 00:17:46.670803 | controller | skipping: Conditional result was False
2025-09-26 00:17:46.687751 | 
2025-09-26 00:17:46.687878 | TASK [Register the RHEL node]
2025-09-26 00:17:46.845579 | 
2025-09-26 00:17:46.845866 | TASK [Show the subscription-manager status]
2025-09-26 00:17:47.035286 | controller | skipping: Conditional result was False
2025-09-26 00:17:47.041168 | 
2025-09-26 00:17:47.041245 | TASK [Enable EPEL on RHEL]
2025-09-26 00:17:47.183729 | controller | skipping: Conditional result was False
2025-09-26 00:17:47.189950 | 
2025-09-26 00:17:47.190039 | TASK [Install git and tox]
2025-09-26 00:19:10.222856 | controller | changed
2025-09-26 00:19:10.235402 | 
2025-09-26 00:19:10.235545 | TASK [include_role : prepare-workspace]
2025-09-26 00:19:10.262417 | controller | ok
2025-09-26 00:19:10.294972 | 
2025-09-26 00:19:10.295111 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-26 00:19:10.862870 | controller | ok
2025-09-26 00:19:10.876114 | 
2025-09-26 00:19:10.876256 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-26 00:19:23.454573 | controller | Output suppressed because no_log was given
2025-09-26 00:19:23.478513 | 
2025-09-26 00:19:23.478655 | TASK [include_role : prepare-workspace-openshift]
2025-09-26 00:19:23.508131 | controller | skipping: Conditional result was False
2025-09-26 00:19:23.553089 | 
2025-09-26 00:19:23.553193 | PLAY [all:!appliance]
2025-09-26 00:19:23.572878 | 
2025-09-26 00:19:23.572964 | TASK [Run add-build-sshkey role (RSA)]
2025-09-26 00:19:23.604984 | controller | ok
2025-09-26 00:19:23.624786 | 
2025-09-26 00:19:23.624876 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-26 00:19:23.948236 | controller -> localhost | ok
2025-09-26 00:19:23.960950 | 
2025-09-26 00:19:23.961129 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-26 00:19:23.996605 | controller | ok
2025-09-26 00:19:24.016411 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-26 00:19:24.024925 | 
2025-09-26 00:19:24.024999 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-26 00:19:24.544451 | controller -> localhost | Generating public/private rsa key pair.
2025-09-26 00:19:24.544766 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_rsa.
2025-09-26 00:19:24.544828 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_rsa.pub.
2025-09-26 00:19:24.544873 | controller -> localhost | The key fingerprint is:
2025-09-26 00:19:24.544915 | controller -> localhost | SHA256:L9Pq9TA9YanD/LjySh7fzxSIjJSPIkdoQcOafxpaMAk zuul-build-sshkey
2025-09-26 00:19:24.544957 | controller -> localhost | The key's randomart image is:
2025-09-26 00:19:24.544997 | controller -> localhost | +---[RSA 2048]----+
2025-09-26 00:19:24.545036 | controller -> localhost | |   o+            |
2025-09-26 00:19:24.545077 | controller -> localhost | |E   .+   .       |
2025-09-26 00:19:24.545116 | controller -> localhost | | . +o . o        |
2025-09-26 00:19:24.545155 | controller -> localhost | |  *. . . = . o   |
2025-09-26 00:19:24.545192 | controller -> localhost | |   +. o S + = .  |
2025-09-26 00:19:24.545253 | controller -> localhost | |    +o.. = + . . |
2025-09-26 00:19:24.545301 | controller -> localhost | |   o +  = @ o .  |
2025-09-26 00:19:24.545342 | controller -> localhost | |  . .  o.B O +   |
2025-09-26 00:19:24.545382 | controller -> localhost | |       .=+=.+.o  |
2025-09-26 00:19:24.545428 | controller -> localhost | +----[SHA256]-----+
2025-09-26 00:19:24.545513 | controller -> localhost | ok: Runtime: 0:00:00.097908
2025-09-26 00:19:24.560403 | 
2025-09-26 00:19:24.560538 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-26 00:19:24.586249 | controller | ok
2025-09-26 00:19:24.600888 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-26 00:19:24.615268 | 
2025-09-26 00:19:24.615386 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-26 00:19:24.650964 | controller | skipping: Conditional result was False
2025-09-26 00:19:24.659803 | 
2025-09-26 00:19:24.659901 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-26 00:19:25.289074 | controller | changed
2025-09-26 00:19:25.302768 | 
2025-09-26 00:19:25.302912 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-26 00:19:25.659861 | controller | ok
2025-09-26 00:19:25.673625 | 
2025-09-26 00:19:25.673810 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-26 00:19:26.989798 | controller | changed
2025-09-26 00:19:27.003521 | 
2025-09-26 00:19:27.003668 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-26 00:19:28.353478 | controller | changed
2025-09-26 00:19:28.359422 | 
2025-09-26 00:19:28.359492 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-26 00:19:28.384371 | controller | skipping: Conditional result was False
2025-09-26 00:19:28.400491 | 
2025-09-26 00:19:28.400666 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-26 00:19:28.806605 | controller -> localhost | changed
2025-09-26 00:19:28.819239 | 
2025-09-26 00:19:28.819342 | TASK [add-build-sshkey : Add back temp key]
2025-09-26 00:19:29.099363 | controller -> localhost | Identity added: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_rsa (zuul-build-sshkey)
2025-09-26 00:19:29.099852 | controller -> localhost | ok: Runtime: 0:00:00.013250
2025-09-26 00:19:29.115220 | 
2025-09-26 00:19:29.115401 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-26 00:19:29.589984 | controller | ok
2025-09-26 00:19:29.601846 | 
2025-09-26 00:19:29.601994 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-26 00:19:29.640310 | controller | skipping: Conditional result was False
2025-09-26 00:19:29.666254 | 
2025-09-26 00:19:29.666439 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-26 00:19:29.708671 | controller | ok
2025-09-26 00:19:29.735990 | 
2025-09-26 00:19:29.736147 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-26 00:19:30.008438 | controller -> localhost | ok
2025-09-26 00:19:30.021366 | 
2025-09-26 00:19:30.021498 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-26 00:19:30.048451 | controller | ok
2025-09-26 00:19:30.070985 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-26 00:19:30.078796 | 
2025-09-26 00:19:30.078881 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-26 00:19:30.379108 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-26 00:19:30.379431 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_ecdsa.
2025-09-26 00:19:30.379504 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_ecdsa.pub.
2025-09-26 00:19:30.379569 | controller -> localhost | The key fingerprint is:
2025-09-26 00:19:30.379617 | controller -> localhost | SHA256:PMUQPvqcc8nuGp19cZUrq23N4PLFp2VktLrAYRVoArE zuul-build-sshkey
2025-09-26 00:19:30.379666 | controller -> localhost | The key's randomart image is:
2025-09-26 00:19:30.379843 | controller -> localhost | +---[ECDSA 521]---+
2025-09-26 00:19:30.379906 | controller -> localhost | |       o=.  ..   |
2025-09-26 00:19:30.379955 | controller -> localhost | |       ..+ o  . .|
2025-09-26 00:19:30.380000 | controller -> localhost | |       Eo =  . .o|
2025-09-26 00:19:30.380044 | controller -> localhost | |       o o  .  .+|
2025-09-26 00:19:30.380091 | controller -> localhost | |      . S  o ..o+|
2025-09-26 00:19:30.380136 | controller -> localhost | |       o =o+..== |
2025-09-26 00:19:30.380181 | controller -> localhost | |        * *ooo=o+|
2025-09-26 00:19:30.380227 | controller -> localhost | |         = .++o*.|
2025-09-26 00:19:30.380274 | controller -> localhost | |        .oo.++.  |
2025-09-26 00:19:30.380320 | controller -> localhost | +----[SHA256]-----+
2025-09-26 00:19:30.380417 | controller -> localhost | ok: Runtime: 0:00:00.008275
2025-09-26 00:19:30.395792 | 
2025-09-26 00:19:30.395932 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-26 00:19:30.434252 | controller | ok
2025-09-26 00:19:30.451444 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-26 00:19:30.469151 | 
2025-09-26 00:19:30.469239 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-26 00:19:30.493773 | controller | skipping: Conditional result was False
2025-09-26 00:19:30.502931 | 
2025-09-26 00:19:30.503020 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-26 00:19:30.966757 | controller | changed
2025-09-26 00:19:30.975010 | 
2025-09-26 00:19:30.975102 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-26 00:19:31.359093 | controller | ok
2025-09-26 00:19:31.371251 | 
2025-09-26 00:19:31.371388 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-26 00:19:32.717104 | controller | changed
2025-09-26 00:19:32.729194 | 
2025-09-26 00:19:32.729344 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-26 00:19:34.051962 | controller | changed
2025-09-26 00:19:34.064963 | 
2025-09-26 00:19:34.065096 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-26 00:19:34.092806 | controller | skipping: Conditional result was False
2025-09-26 00:19:34.109830 | 
2025-09-26 00:19:34.110001 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-26 00:19:34.411395 | controller -> localhost | changed
2025-09-26 00:19:34.426758 | 
2025-09-26 00:19:34.426842 | TASK [add-build-sshkey : Add back temp key]
2025-09-26 00:19:34.734732 | controller -> localhost | Identity added: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/259735b00fdc4cdaada37ca27991025d_id_ecdsa (zuul-build-sshkey)
2025-09-26 00:19:34.734930 | controller -> localhost | ok: Runtime: 0:00:00.007253
2025-09-26 00:19:34.740929 | 
2025-09-26 00:19:34.741009 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-26 00:19:35.112623 | controller | ok
2025-09-26 00:19:35.123989 | 
2025-09-26 00:19:35.124122 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-26 00:19:35.160841 | controller | skipping: Conditional result was False
2025-09-26 00:19:35.184032 | 
2025-09-26 00:19:35.184244 | TASK [include_role : remove-zuul-sshkey]
2025-09-26 00:19:35.210865 | controller | skipping: Conditional result was False
2025-09-26 00:19:35.225395 | 
2025-09-26 00:19:35.225557 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-26 00:19:35.561947 | controller | ok: "logs"
2025-09-26 00:19:35.562377 | controller | ok: All items complete
2025-09-26 00:19:35.562436 | 
2025-09-26 00:19:35.887851 | controller | ok: "artifacts"
2025-09-26 00:19:36.191950 | controller | ok: "docs"
2025-09-26 00:19:36.206171 | 
2025-09-26 00:19:36.206340 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-26 00:19:36.551340 | controller | changed: "logs"
2025-09-26 00:19:36.859236 | controller | changed: "artifacts"
2025-09-26 00:19:37.177981 | controller | changed: "docs"
2025-09-26 00:19:37.234334 | 
2025-09-26 00:19:37.234434 | PLAY RECAP
2025-09-26 00:19:37.234488 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-26 00:19:37.234523 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-26 00:19:37.234547 | 
2025-09-26 00:19:37.335588 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-26 00:19:37.336417 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-26 00:19:37.921012 | 
2025-09-26 00:19:37.921160 | PLAY [all]
2025-09-26 00:19:37.943944 | 
2025-09-26 00:19:37.944045 | TASK [Install binary dependencies]
2025-09-26 00:19:37.992637 | controller | ok
2025-09-26 00:19:38.011721 | 
2025-09-26 00:19:38.011808 | TASK [bindep : Include find tasks]
2025-09-26 00:19:38.041765 | controller | ok
2025-09-26 00:19:38.049913 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-26 00:19:38.056227 | 
2025-09-26 00:19:38.056294 | TASK [bindep : Look for bindep.txt]
2025-09-26 00:19:38.573238 | controller | ok
2025-09-26 00:19:38.586846 | 
2025-09-26 00:19:38.587007 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:19:38.615239 | controller | skipping: Conditional result was False
2025-09-26 00:19:38.627827 | 
2025-09-26 00:19:38.627972 | TASK [bindep : Look for other-requirements.txt]
2025-09-26 00:19:38.953454 | controller | ok
2025-09-26 00:19:38.965878 | 
2025-09-26 00:19:38.966037 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:19:39.007106 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.018863 | 
2025-09-26 00:19:39.019001 | TASK [bindep : Look for bindep fallback file]
2025-09-26 00:19:39.046264 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.058206 | 
2025-09-26 00:19:39.058338 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:19:39.085413 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.094335 | 
2025-09-26 00:19:39.094427 | TASK [bindep : Include bindep tasks]
2025-09-26 00:19:39.140581 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.148739 | 
2025-09-26 00:19:39.148808 | TASK [bindep : Include install tasks]
2025-09-26 00:19:39.183154 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.189312 | 
2025-09-26 00:19:39.189379 | LOOP [bindep : Include package tasks]
2025-09-26 00:19:39.257593 | 
2025-09-26 00:19:39.257818 | TASK [Run test-setup role]
2025-09-26 00:19:39.285170 | controller | ok
2025-09-26 00:19:39.311183 | 
2025-09-26 00:19:39.311292 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-26 00:19:39.624706 | controller | ok
2025-09-26 00:19:39.637939 | 
2025-09-26 00:19:39.638075 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-26 00:19:39.790755 | controller | skipping: Conditional result was False
2025-09-26 00:19:39.842711 | 
2025-09-26 00:19:39.842819 | PLAY RECAP
2025-09-26 00:19:39.842875 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-26 00:19:39.842904 | 
2025-09-26 00:19:39.943814 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-26 00:19:39.945466 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-26 00:19:40.530650 | 
2025-09-26 00:19:40.530795 | PLAY [controller]
2025-09-26 00:19:40.549720 | 
2025-09-26 00:19:40.549803 | TASK [Create the /root directory]
2025-09-26 00:19:41.353189 | controller | ok
2025-09-26 00:19:41.368946 | 
2025-09-26 00:19:41.369166 | TASK [Install glibc-langpack-en]
2025-09-26 00:19:49.651074 | controller | ok: Nothing to do
2025-09-26 00:19:49.664046 | 
2025-09-26 00:19:49.664191 | TASK [Ensure controller directory exists]
2025-09-26 00:19:50.152634 | controller | changed
2025-09-26 00:19:50.166008 | 
2025-09-26 00:19:50.166193 | TASK [Install container runtime]
2025-09-26 00:19:50.243306 | controller | ok
2025-09-26 00:19:50.290959 | 
2025-09-26 00:19:50.291097 | LOOP [ensure-podman : Find distribution installation]
2025-09-26 00:19:50.321546 | controller | ok: "/var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-26 00:19:50.335307 | controller | included: /var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-26 00:19:50.341885 | 
2025-09-26 00:19:50.341957 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-26 00:21:09.927835 | controller | changed
2025-09-26 00:21:09.934287 | 
2025-09-26 00:21:09.934352 | TASK [ensure-podman : Fetch podman version]
2025-09-26 00:21:10.628648 | controller | Client:       Podman Engine
2025-09-26 00:21:10.628728 | controller | Version:      4.6.2
2025-09-26 00:21:10.628759 | controller | API Version:  4.6.2
2025-09-26 00:21:10.628785 | controller | Go Version:   go1.19.12
2025-09-26 00:21:10.628821 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-26 00:21:10.628849 | controller | OS/Arch:      linux/amd64
2025-09-26 00:21:11.072434 | controller | ok: Runtime: 0:00:00.187191
2025-09-26 00:21:11.087869 | 
2025-09-26 00:21:11.088043 | TASK [ensure-podman : Print podman version installed]
2025-09-26 00:21:11.132221 | Podman version: Client:       Podman Engine
2025-09-26 00:21:11.132490 | Version:      4.6.2
2025-09-26 00:21:11.132554 | API Version:  4.6.2
2025-09-26 00:21:11.132602 | Go Version:   go1.19.12
2025-09-26 00:21:11.132641 | Built:        Mon Aug 28 19:38:31 2023
2025-09-26 00:21:11.132739 | OS/Arch:      linux/amd64
2025-09-26 00:21:11.149836 | 
2025-09-26 00:21:11.150280 | TASK [ensure-podman : Validate podman engine]
2025-09-26 00:21:11.294280 | controller | skipping: Conditional result was False
2025-09-26 00:21:11.310194 | 
2025-09-26 00:21:11.310444 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-26 00:21:11.338785 | controller | skipping: Conditional result was False
2025-09-26 00:21:11.357585 | 
2025-09-26 00:21:11.357725 | TASK [Ensure python3.8 is present]
2025-09-26 00:21:11.385943 | controller | skipping: Conditional result was False
2025-09-26 00:21:11.397886 | 
2025-09-26 00:21:11.398007 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-26 00:21:11.432368 | controller | ok
2025-09-26 00:21:11.466123 | 
2025-09-26 00:21:11.466277 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-26 00:21:15.191761 | controller | ok: Nothing to do
2025-09-26 00:21:15.202387 | 
2025-09-26 00:21:15.202510 | TASK [our-ensure-python : Also install python3-devel]
2025-09-26 00:21:28.337741 | controller | changed
2025-09-26 00:21:28.354448 | 
2025-09-26 00:21:28.354565 | TASK [Run ensure-virtualenv role]
2025-09-26 00:21:28.390543 | controller | ok
2025-09-26 00:21:28.424923 | 
2025-09-26 00:21:28.425141 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-26 00:21:28.797866 | controller | /usr/bin/virtualenv
2025-09-26 00:21:29.068392 | controller | ok: Runtime: 0:00:00.004507
2025-09-26 00:21:29.087769 | 
2025-09-26 00:21:29.088024 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-26 00:21:29.125522 | controller | skipping: Conditional result was False
2025-09-26 00:21:29.126055 | controller | ok: All items complete
2025-09-26 00:21:29.126119 | 
2025-09-26 00:21:29.153285 | 
2025-09-26 00:21:29.153825 | TASK [Find the full path of the Python interpreter]
2025-09-26 00:21:29.633231 | controller | /usr/bin/python3
2025-09-26 00:21:29.832331 | controller | ok
2025-09-26 00:21:29.839852 | 
2025-09-26 00:21:29.839926 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-26 00:21:31.341919 | controller | created virtual environment CPython3.11.0.final.0-64 in 784ms
2025-09-26 00:21:31.385846 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-26 00:21:31.385904 | 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-09-26 00:21:31.385923 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-26 00:21:31.385946 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-26 00:21:31.497220 | controller | changed
2025-09-26 00:21:31.511351 | 
2025-09-26 00:21:31.511573 | TASK [Set selinux package]
2025-09-26 00:21:31.550837 | controller | ok
2025-09-26 00:21:31.561405 | 
2025-09-26 00:21:31.561565 | TASK [Set selinux package (Fedora)]
2025-09-26 00:21:31.619848 | controller | ok
2025-09-26 00:21:31.631454 | 
2025-09-26 00:21:31.631602 | TASK [Install selinux into virtualenv]
2025-09-26 00:21:34.291306 | controller | Collecting selinux-please-lie-to-me
2025-09-26 00:21:34.378102 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-26 00:21:34.911500 | controller | Collecting setuptools<50.0.0
2025-09-26 00:21:34.927404 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-26 00:21:34.988360 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 15.1 MB/s eta 0:00:00
2025-09-26 00:21:35.145376 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-26 00:21:35.145706 | controller |   Attempting uninstall: setuptools
2025-09-26 00:21:35.150711 | controller |     Found existing installation: setuptools 62.6.0
2025-09-26 00:21:35.264060 | controller |     Uninstalling setuptools-62.6.0:
2025-09-26 00:21:35.279248 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-26 00:21:36.033978 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-26 00:21:36.247353 | controller |
2025-09-26 00:21:36.463355 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-26 00:21:36.463400 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-26 00:21:36.802391 | controller | ok: Runtime: 0:00:04.322643
2025-09-26 00:21:36.817809 | 
2025-09-26 00:21:36.818044 | TASK [Install pytest-forked into virtualenv]
2025-09-26 00:21:38.065969 | controller | Collecting pytest-forked
2025-09-26 00:21:38.155920 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-26 00:21:38.218034 | controller | Collecting py
2025-09-26 00:21:38.231896 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-26 00:21:38.267404 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-09-26 00:21:38.445402 | controller | Collecting pytest>=3.10
2025-09-26 00:21:38.458268 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-26 00:21:38.517433 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.5 MB/s eta 0:00:00
2025-09-26 00:21:38.572915 | controller | Collecting iniconfig>=1
2025-09-26 00:21:38.585456 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-26 00:21:38.653668 | controller | Collecting packaging>=20
2025-09-26 00:21:38.665577 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-26 00:21:38.677750 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00
2025-09-26 00:21:38.724328 | controller | Collecting pluggy<2,>=1.5
2025-09-26 00:21:38.736418 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-26 00:21:38.811987 | controller | Collecting pygments>=2.7.2
2025-09-26 00:21:38.825564 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-26 00:21:38.943157 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-09-26 00:21:39.076193 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-26 00:21:41.402976 | 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-09-26 00:21:41.419173 | controller |
2025-09-26 00:21:41.608492 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-26 00:21:41.608545 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-26 00:21:41.994572 | controller | ok: Runtime: 0:00:04.285704
2025-09-26 00:21:42.007044 | 
2025-09-26 00:21:42.007207 | TASK [Update pip]
2025-09-26 00:21:43.117744 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-26 00:21:43.394361 | controller | Collecting pip
2025-09-26 00:21:43.495287 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-26 00:21:43.676288 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.9 MB/s eta 0:00:00
2025-09-26 00:21:43.846377 | controller | Installing collected packages: pip
2025-09-26 00:21:43.847375 | controller |   Attempting uninstall: pip
2025-09-26 00:21:43.855030 | controller |     Found existing installation: pip 22.2.2
2025-09-26 00:21:44.146691 | controller |     Uninstalling pip-22.2.2:
2025-09-26 00:21:44.176426 | controller |       Successfully uninstalled pip-22.2.2
2025-09-26 00:21:45.970093 | controller | Successfully installed pip-25.2
2025-09-26 00:21:46.675320 | controller | ok: Runtime: 0:00:03.655991
2025-09-26 00:21:46.686401 | 
2025-09-26 00:21:46.686569 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-26 00:21:47.230783 | controller | changed
2025-09-26 00:21:47.242340 | 
2025-09-26 00:21:47.242477 | TASK [Install ansible into virtualenv]
2025-09-26 00:21:48.451645 | controller | Processing ./src/github.com/ansible/ansible
2025-09-26 00:21:48.458294 | controller |   Installing build dependencies: started
2025-09-26 00:21:50.470586 | controller |   Installing build dependencies: finished with status 'done'
2025-09-26 00:21:52.013621 | controller |   Getting requirements to build wheel: started
2025-09-26 00:21:52.013678 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-26 00:21:52.940191 | controller |   Preparing metadata (pyproject.toml): started
2025-09-26 00:21:52.940247 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-26 00:21:52.942778 | 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-09-26 00:21:52.947620 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-26 00:21:53.413969 | controller | ERROR
2025-09-26 00:21:53.414197 | controller | {
2025-09-26 00:21:53.414240 | controller |   "delta": "0:00:05.408044",
2025-09-26 00:21:53.414269 | controller |   "end": "2025-09-26 00:21:53.099340",
2025-09-26 00:21:53.414296 | controller |   "msg": "non-zero return code",
2025-09-26 00:21:53.414334 | controller |   "rc": 1,
2025-09-26 00:21:53.414360 | controller |   "start": "2025-09-26 00:21:47.691296"
2025-09-26 00:21:53.414384 | controller | }
failure
2025-09-26 00:21:53.416624 | 
2025-09-26 00:21:53.416727 | PLAY RECAP
2025-09-26 00:21:53.416794 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-26 00:21:53.416825 | 
2025-09-26 00:21:53.537325 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-26 00:21:53.538524 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-26 00:21:54.168652 | 
2025-09-26 00:21:54.168819 | PLAY [all]
2025-09-26 00:21:54.190462 | 
2025-09-26 00:21:54.190588 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-26 00:21:55.018377 | controller | changed: non-zero return code
2025-09-26 00:21:55.030901 | 
2025-09-26 00:21:55.031099 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-26 00:21:55.060207 | controller | skipping: Conditional result was False
2025-09-26 00:21:55.072948 | 
2025-09-26 00:21:55.073096 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-26 00:21:55.113860 | 
2025-09-26 00:21:55.114125 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-26 00:21:55.154068 | 
2025-09-26 00:21:55.154342 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-26 00:21:55.172178 | controller | skipping: Conditional result was False
2025-09-26 00:21:55.185881 | 
2025-09-26 00:21:55.186040 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-26 00:21:55.221869 | 
2025-09-26 00:21:55.222051 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-26 00:21:55.246891 | controller | skipping: Conditional result was False
2025-09-26 00:21:55.254938 | 
2025-09-26 00:21:55.255032 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-26 00:21:55.270076 | controller | skipping: Conditional result was False
2025-09-26 00:21:55.285804 | 
2025-09-26 00:21:55.285959 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-26 00:21:55.303449 | controller | skipping: Conditional result was False
2025-09-26 00:21:55.357602 | 
2025-09-26 00:21:55.357741 | PLAY RECAP
2025-09-26 00:21:55.357798 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-26 00:21:55.357826 | 
2025-09-26 00:21:55.509316 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-26 00:21:55.510542 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-26 00:21:56.110851 | 
2025-09-26 00:21:56.111012 | PLAY [all:!appliance*]
2025-09-26 00:21:56.137123 | 
2025-09-26 00:21:56.137288 | TASK [unregister the node]
2025-09-26 00:21:56.270392 | controller | skipping: Conditional result was False
2025-09-26 00:21:56.279321 | 
2025-09-26 00:21:56.279493 | TASK [include_role : fetch-output]
2025-09-26 00:21:56.312744 | controller | ok
2025-09-26 00:21:56.338542 | 
2025-09-26 00:21:56.338707 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-26 00:21:56.405445 | controller | skipping: Conditional result was False
2025-09-26 00:21:56.414415 | 
2025-09-26 00:21:56.414591 | TASK [fetch-output : Set log path for single node]
2025-09-26 00:21:56.458849 | controller | ok
2025-09-26 00:21:56.466096 | 
2025-09-26 00:21:56.466181 | LOOP [fetch-output : Ensure local output dirs]
2025-09-26 00:21:56.896279 | controller -> localhost | ok: "/var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/logs"
2025-09-26 00:21:57.180219 | controller -> localhost | changed: "/var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/artifacts"
2025-09-26 00:21:57.403840 | controller -> localhost | changed: "/var/lib/zuul/builds/259735b00fdc4cdaada37ca27991025d/work/docs"
2025-09-26 00:21:57.419111 | 
2025-09-26 00:21:57.419235 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-26 00:21:58.632977 | controller | changed:
2025-09-26 00:21:58.633219 | controller | .d..t...... ./
2025-09-26 00:21:58.633267 | controller | cd+++++++++ controller/
2025-09-26 00:21:58.633323 | controller | changed: All items complete
2025-09-26 00:21:58.633358 | 
2025-09-26 00:21:59.668879 | controller | changed: .d..t...... ./
2025-09-26 00:22:00.734815 | controller | changed: .d..t...... ./
2025-09-26 00:22:00.770979 | 
2025-09-26 00:22:00.771263 | TASK [include_role : fetch-output-openshift]
2025-09-26 00:22:00.798360 | controller | skipping: Conditional result was False
2025-09-26 00:22:00.807422 | 
2025-09-26 00:22:00.807516 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-26 00:22:00.844763 | controller | skipping: Conditional result was False
2025-09-26 00:22:00.856928 | controller | skipping: Conditional result was False
2025-09-26 00:22:00.901926 | 
2025-09-26 00:22:00.902073 | PLAY [localhost]
2025-09-26 00:22:00.920499 | 
2025-09-26 00:22:00.920591 | TASK [Run Zuul manifest role]
2025-09-26 00:22:00.952025 | localhost | ok
2025-09-26 00:22:00.971398 | 
2025-09-26 00:22:00.971496 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-26 00:22:01.384310 | localhost | changed
2025-09-26 00:22:01.396432 | 
2025-09-26 00:22:01.396573 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-26 00:22:01.434417 | localhost | ok
2025-09-26 00:22:01.453289 | 
2025-09-26 00:22:01.453414 | TASK [Set zuul-log-path fact]
2025-09-26 00:22:01.478799 | localhost | ok
2025-09-26 00:22:01.504062 | 
2025-09-26 00:22:01.504249 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-26 00:22:01.534383 | localhost | ok
2025-09-26 00:22:01.543303 | 
2025-09-26 00:22:01.543389 | LOOP [Run upload-logs-swift role]
2025-09-26 00:22:01.578741 | localhost | Output suppressed because no_log was given
2025-09-26 00:22:01.612170 | 
2025-09-26 00:22:01.612304 | TASK [Set zuul-log-path fact]
2025-09-26 00:22:01.649433 | localhost | skipping: Conditional result was False
2025-09-26 00:22:01.658161 | 
2025-09-26 00:22:01.658323 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-26 00:22:02.092561 | localhost -> localhost | ok: Runtime: 0:00:00.009802
2025-09-26 00:22:02.105029 | 
2025-09-26 00:22:02.105180 | TASK [upload-logs-swift : Upload logs to swift]