2025-10-26 00:17:38.592732 | Job console starting...
2025-10-26 00:17:38.606537 | Updating repositories
2025-10-26 00:17:38.831318 | Preparing job workspace
2025-10-26 00:17:43.577995 | Running Ansible setup...
2025-10-26 00:17:49.777032 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-26 00:17:50.447273 | 
2025-10-26 00:17:50.447592 | PLAY [localhost]
2025-10-26 00:17:50.457888 | 
2025-10-26 00:17:50.457968 | TASK [Gathering Facts]
2025-10-26 00:17:51.589506 | localhost | ok
2025-10-26 00:17:51.622183 | 
2025-10-26 00:17:51.622505 | TASK [Setup log path fact]
2025-10-26 00:17:51.647780 | localhost | ok
2025-10-26 00:17:51.665998 | 
2025-10-26 00:17:51.666183 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-26 00:17:51.713430 | localhost | ok
2025-10-26 00:17:51.728403 | 
2025-10-26 00:17:51.728506 | TASK [emit-job-header : Print job information]
2025-10-26 00:17:51.770781 | # Job Information
2025-10-26 00:17:51.770971 | Ansible Version: 2.15.12
2025-10-26 00:17:51.771016 | Job: ansible-test-sanity-docker-devel
2025-10-26 00:17:51.771045 | Pipeline: periodic
2025-10-26 00:17:51.771070 | Executor: ze02.softwarefactory-project.io
2025-10-26 00:17:51.771096 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-26 00:17:51.771124 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/3df/ansible/3df9c94bbbd6429bb11b638bdf0c4ea1/
2025-10-26 00:17:51.771151 | Event ID: c2e72cdc87924775bd86541f38e3bebc
2025-10-26 00:17:51.777052 | 
2025-10-26 00:17:51.777146 | LOOP [emit-job-header : Print node information]
2025-10-26 00:17:51.910421 | localhost | ok:
2025-10-26 00:17:51.910858 | localhost | # Node Information
2025-10-26 00:17:51.910901 | localhost | Inventory Hostname: controller
2025-10-26 00:17:51.910929 | localhost | Hostname: ip-172-16-109-217
2025-10-26 00:17:51.910954 | localhost | Username: zuul-worker
2025-10-26 00:17:51.910983 | localhost | Distro: Fedora 37
2025-10-26 00:17:51.911008 | localhost | Provider: ansible-us-east-2
2025-10-26 00:17:51.911032 | localhost | Region: us-east-2
2025-10-26 00:17:51.911056 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-26 00:17:51.911078 | localhost | Product Name: t3.small
2025-10-26 00:17:51.911104 | localhost | Interface IP: 3.129.65.59
2025-10-26 00:17:51.933046 | 
2025-10-26 00:17:51.933301 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-26 00:17:52.398527 | localhost -> localhost | changed
2025-10-26 00:17:52.411975 | 
2025-10-26 00:17:52.412134 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-26 00:17:53.507266 | localhost -> localhost | changed
2025-10-26 00:17:53.554947 | 
2025-10-26 00:17:53.555035 | PLAY [all:!appliance*]
2025-10-26 00:17:53.579466 | 
2025-10-26 00:17:53.579560 | TASK [include_role : start-zuul-console]
2025-10-26 00:17:53.603934 | controller | ok
2025-10-26 00:17:53.625161 | 
2025-10-26 00:17:53.625253 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-26 00:17:54.328585 | controller | ok
2025-10-26 00:17:54.353544 | 
2025-10-26 00:17:54.353932 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-26 00:17:57.539110 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-26 00:17:57.553802 | 
2025-10-26 00:17:57.554000 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-26 00:17:57.710749 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.717996 | 
2025-10-26 00:17:57.718140 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-26 00:17:57.743301 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.750465 | 
2025-10-26 00:17:57.750620 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-26 00:17:57.777469 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.792222 | 
2025-10-26 00:17:57.792469 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-26 00:17:57.820713 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.835448 | 
2025-10-26 00:17:57.835702 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-26 00:17:57.865316 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.875211 | 
2025-10-26 00:17:57.875321 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-26 00:17:57.901129 | controller | skipping: Conditional result was False
2025-10-26 00:17:57.918903 | 
2025-10-26 00:17:57.919117 | TASK [Disable Fedora Modular]
2025-10-26 00:17:58.724101 | controller | changed
2025-10-26 00:17:58.735221 | 
2025-10-26 00:17:58.735354 | TASK [Enable EPEL]
2025-10-26 00:17:58.761592 | controller | skipping: Conditional result was False
2025-10-26 00:17:58.770196 | 
2025-10-26 00:17:58.770293 | TASK [Register the RHEL node]
2025-10-26 00:17:58.919071 | 
2025-10-26 00:17:58.919285 | TASK [Show the subscription-manager status]
2025-10-26 00:17:59.101407 | controller | skipping: Conditional result was False
2025-10-26 00:17:59.108071 | 
2025-10-26 00:17:59.108142 | TASK [Enable EPEL on RHEL]
2025-10-26 00:17:59.261996 | controller | skipping: Conditional result was False
2025-10-26 00:17:59.269099 | 
2025-10-26 00:17:59.269180 | TASK [Install git and tox]
2025-10-26 00:19:30.670694 | controller | changed
2025-10-26 00:19:30.681584 | 
2025-10-26 00:19:30.681765 | TASK [include_role : prepare-workspace]
2025-10-26 00:19:30.715733 | controller | ok
2025-10-26 00:19:30.743160 | 
2025-10-26 00:19:30.743252 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-26 00:19:31.287653 | controller | ok
2025-10-26 00:19:31.297799 | 
2025-10-26 00:19:31.297944 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-26 00:19:44.361630 | controller | Output suppressed because no_log was given
2025-10-26 00:19:44.381533 | 
2025-10-26 00:19:44.381727 | TASK [include_role : prepare-workspace-openshift]
2025-10-26 00:19:44.408242 | controller | skipping: Conditional result was False
2025-10-26 00:19:44.441970 | 
2025-10-26 00:19:44.442061 | PLAY [all:!appliance]
2025-10-26 00:19:44.500763 | 
2025-10-26 00:19:44.500897 | TASK [Run add-build-sshkey role (RSA)]
2025-10-26 00:19:44.531428 | controller | ok
2025-10-26 00:19:44.547884 | 
2025-10-26 00:19:44.547960 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-26 00:19:44.847362 | controller -> localhost | ok
2025-10-26 00:19:44.857192 | 
2025-10-26 00:19:44.857361 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-26 00:19:44.894611 | controller | ok
2025-10-26 00:19:44.916903 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-26 00:19:44.923682 | 
2025-10-26 00:19:44.923821 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-26 00:19:45.419061 | controller -> localhost | Generating public/private rsa key pair.
2025-10-26 00:19:45.419320 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_rsa.
2025-10-26 00:19:45.419349 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_rsa.pub.
2025-10-26 00:19:45.419392 | controller -> localhost | The key fingerprint is:
2025-10-26 00:19:45.419416 | controller -> localhost | SHA256:2tNvaM39CXJcWbZDzLevIlBh7MCy2xaIFUm5Kjd2YOM zuul-build-sshkey
2025-10-26 00:19:45.419436 | controller -> localhost | The key's randomart image is:
2025-10-26 00:19:45.419455 | controller -> localhost | +---[RSA 2048]----+
2025-10-26 00:19:45.419473 | controller -> localhost | |     .o= .       |
2025-10-26 00:19:45.419492 | controller -> localhost | |      = o +   o  |
2025-10-26 00:19:45.419510 | controller -> localhost | |     o = + .   ++|
2025-10-26 00:19:45.419527 | controller -> localhost | |    = + . o   ..*|
2025-10-26 00:19:45.419545 | controller -> localhost | |   o + oSo     * |
2025-10-26 00:19:45.419572 | controller -> localhost | |  . E oo+.  . . o|
2025-10-26 00:19:45.419594 | controller -> localhost | |   + o..o..= =  .|
2025-10-26 00:19:45.419614 | controller -> localhost | |         .+.B o..|
2025-10-26 00:19:45.419633 | controller -> localhost | |         . o...o.|
2025-10-26 00:19:45.419653 | controller -> localhost | +----[SHA256]-----+
2025-10-26 00:19:45.419722 | controller -> localhost | ok: Runtime: 0:00:00.129251
2025-10-26 00:19:45.426798 | 
2025-10-26 00:19:45.426883 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-26 00:19:45.461434 | controller | ok
2025-10-26 00:19:45.473307 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-26 00:19:45.483750 | 
2025-10-26 00:19:45.483900 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-26 00:19:45.510542 | controller | skipping: Conditional result was False
2025-10-26 00:19:45.517573 | 
2025-10-26 00:19:45.517700 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-26 00:19:46.239923 | controller | changed
2025-10-26 00:19:46.250039 | 
2025-10-26 00:19:46.250188 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-26 00:19:46.617346 | controller | ok
2025-10-26 00:19:46.627585 | 
2025-10-26 00:19:46.627737 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-26 00:19:47.983250 | controller | changed
2025-10-26 00:19:47.996314 | 
2025-10-26 00:19:47.996480 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-26 00:19:49.326456 | controller | changed
2025-10-26 00:19:49.338859 | 
2025-10-26 00:19:49.338996 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-26 00:19:49.367930 | controller | skipping: Conditional result was False
2025-10-26 00:19:49.382705 | 
2025-10-26 00:19:49.382876 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-26 00:19:49.805398 | controller -> localhost | changed
2025-10-26 00:19:49.832861 | 
2025-10-26 00:19:49.833058 | TASK [add-build-sshkey : Add back temp key]
2025-10-26 00:19:50.127651 | controller -> localhost | Identity added: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_rsa (zuul-build-sshkey)
2025-10-26 00:19:50.127980 | controller -> localhost | ok: Runtime: 0:00:00.008623
2025-10-26 00:19:50.135706 | 
2025-10-26 00:19:50.135775 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-26 00:19:50.728574 | controller | ok
2025-10-26 00:19:50.741908 | 
2025-10-26 00:19:50.742097 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-26 00:19:50.781509 | controller | skipping: Conditional result was False
2025-10-26 00:19:50.805710 | 
2025-10-26 00:19:50.805855 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-26 00:19:50.857520 | controller | ok
2025-10-26 00:19:50.880443 | 
2025-10-26 00:19:50.880604 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-26 00:19:51.173786 | controller -> localhost | ok
2025-10-26 00:19:51.181447 | 
2025-10-26 00:19:51.181528 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-26 00:19:51.201550 | controller | ok
2025-10-26 00:19:51.214212 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-26 00:19:51.221711 | 
2025-10-26 00:19:51.221779 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-26 00:19:51.521687 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-26 00:19:51.521989 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_ecdsa.
2025-10-26 00:19:51.522052 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_ecdsa.pub.
2025-10-26 00:19:51.522092 | controller -> localhost | The key fingerprint is:
2025-10-26 00:19:51.522121 | controller -> localhost | SHA256:Y4CBMeqvfc/2lGrX3N7ABAKBtcjMqC3R2pmeg5y7cQA zuul-build-sshkey
2025-10-26 00:19:51.522148 | controller -> localhost | The key's randomart image is:
2025-10-26 00:19:51.522175 | controller -> localhost | +---[ECDSA 521]---+
2025-10-26 00:19:51.522201 | controller -> localhost | |  oo. o+.        |
2025-10-26 00:19:51.522227 | controller -> localhost | | .o.=+. o        |
2025-10-26 00:19:51.522252 | controller -> localhost | |E. o.=.. . .     |
2025-10-26 00:19:51.522277 | controller -> localhost | |o * o  .  . .    |
2025-10-26 00:19:51.522301 | controller -> localhost | | * =    S    .   |
2025-10-26 00:19:51.522326 | controller -> localhost | |. B .  . .. o    |
2025-10-26 00:19:51.522351 | controller -> localhost | | = *     oo .o   |
2025-10-26 00:19:51.522375 | controller -> localhost | |  * ...oo. o .o  |
2025-10-26 00:19:51.522399 | controller -> localhost | | +... ++o.  .. . |
2025-10-26 00:19:51.522423 | controller -> localhost | +----[SHA256]-----+
2025-10-26 00:19:51.522496 | controller -> localhost | ok: Runtime: 0:00:00.010822
2025-10-26 00:19:51.533100 | 
2025-10-26 00:19:51.533197 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-26 00:19:51.571156 | controller | ok
2025-10-26 00:19:51.582509 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-26 00:19:51.595751 | 
2025-10-26 00:19:51.595852 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-26 00:19:51.627591 | controller | skipping: Conditional result was False
2025-10-26 00:19:51.639015 | 
2025-10-26 00:19:51.639153 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-26 00:19:52.132154 | controller | changed
2025-10-26 00:19:52.143206 | 
2025-10-26 00:19:52.143358 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-26 00:19:52.500374 | controller | ok
2025-10-26 00:19:52.511272 | 
2025-10-26 00:19:52.511418 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-26 00:19:53.848606 | controller | changed
2025-10-26 00:19:53.861337 | 
2025-10-26 00:19:53.861482 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-26 00:19:55.215551 | controller | changed
2025-10-26 00:19:55.226441 | 
2025-10-26 00:19:55.226577 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-26 00:19:55.252402 | controller | skipping: Conditional result was False
2025-10-26 00:19:55.262213 | 
2025-10-26 00:19:55.262338 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-26 00:19:55.545199 | controller -> localhost | changed
2025-10-26 00:19:55.569396 | 
2025-10-26 00:19:55.569555 | TASK [add-build-sshkey : Add back temp key]
2025-10-26 00:19:55.913591 | controller -> localhost | Identity added: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/3df9c94bbbd6429bb11b638bdf0c4ea1_id_ecdsa (zuul-build-sshkey)
2025-10-26 00:19:55.913939 | controller -> localhost | ok: Runtime: 0:00:00.008144
2025-10-26 00:19:55.921449 | 
2025-10-26 00:19:55.921517 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-26 00:19:56.285354 | controller | ok
2025-10-26 00:19:56.300493 | 
2025-10-26 00:19:56.300634 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-26 00:19:56.389687 | controller | skipping: Conditional result was False
2025-10-26 00:19:56.447226 | 
2025-10-26 00:19:56.447367 | TASK [include_role : remove-zuul-sshkey]
2025-10-26 00:19:56.462244 | controller | skipping: Conditional result was False
2025-10-26 00:19:56.469254 | 
2025-10-26 00:19:56.469319 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-26 00:19:57.404018 | controller | ok: "logs"
2025-10-26 00:19:57.404462 | controller | ok: All items complete
2025-10-26 00:19:57.404522 | 
2025-10-26 00:19:57.701058 | controller | ok: "artifacts"
2025-10-26 00:19:57.984026 | controller | ok: "docs"
2025-10-26 00:19:57.994263 | 
2025-10-26 00:19:57.994356 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-26 00:19:58.333448 | controller | changed: "logs"
2025-10-26 00:19:58.620089 | controller | changed: "artifacts"
2025-10-26 00:19:58.912974 | controller | changed: "docs"
2025-10-26 00:19:58.958862 | 
2025-10-26 00:19:58.959024 | PLAY RECAP
2025-10-26 00:19:58.959104 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-26 00:19:58.959154 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-26 00:19:58.959189 | 
2025-10-26 00:19:59.135644 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-26 00:19:59.136619 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-26 00:19:59.763027 | 
2025-10-26 00:19:59.763160 | PLAY [all]
2025-10-26 00:19:59.785522 | 
2025-10-26 00:19:59.785692 | TASK [Install binary dependencies]
2025-10-26 00:19:59.846405 | controller | ok
2025-10-26 00:19:59.867138 | 
2025-10-26 00:19:59.867273 | TASK [bindep : Include find tasks]
2025-10-26 00:19:59.906907 | controller | ok
2025-10-26 00:19:59.914536 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-26 00:19:59.920504 | 
2025-10-26 00:19:59.920574 | TASK [bindep : Look for bindep.txt]
2025-10-26 00:20:00.469220 | controller | ok
2025-10-26 00:20:00.483425 | 
2025-10-26 00:20:00.483578 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:20:00.511679 | controller | skipping: Conditional result was False
2025-10-26 00:20:00.521538 | 
2025-10-26 00:20:00.521713 | TASK [bindep : Look for other-requirements.txt]
2025-10-26 00:20:00.843834 | controller | ok
2025-10-26 00:20:00.856138 | 
2025-10-26 00:20:00.856286 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:20:00.883468 | controller | skipping: Conditional result was False
2025-10-26 00:20:00.896971 | 
2025-10-26 00:20:00.897121 | TASK [bindep : Look for bindep fallback file]
2025-10-26 00:20:00.924634 | controller | skipping: Conditional result was False
2025-10-26 00:20:00.938176 | 
2025-10-26 00:20:00.938377 | TASK [bindep : Define bindep_file fact]
2025-10-26 00:20:00.965643 | controller | skipping: Conditional result was False
2025-10-26 00:20:00.978443 | 
2025-10-26 00:20:00.978615 | TASK [bindep : Include bindep tasks]
2025-10-26 00:20:01.005800 | controller | skipping: Conditional result was False
2025-10-26 00:20:01.021465 | 
2025-10-26 00:20:01.021629 | TASK [bindep : Include install tasks]
2025-10-26 00:20:01.048416 | controller | skipping: Conditional result was False
2025-10-26 00:20:01.055615 | 
2025-10-26 00:20:01.055713 | LOOP [bindep : Include package tasks]
2025-10-26 00:20:01.123005 | 
2025-10-26 00:20:01.123326 | TASK [Run test-setup role]
2025-10-26 00:20:01.146385 | controller | ok
2025-10-26 00:20:01.173440 | 
2025-10-26 00:20:01.173801 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-26 00:20:02.106822 | controller | ok
2025-10-26 00:20:02.117130 | 
2025-10-26 00:20:02.117218 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-26 00:20:02.264727 | controller | skipping: Conditional result was False
2025-10-26 00:20:02.316104 | 
2025-10-26 00:20:02.316239 | PLAY RECAP
2025-10-26 00:20:02.316298 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-26 00:20:02.316327 | 
2025-10-26 00:20:02.493368 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-26 00:20:02.495128 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-26 00:20:03.118867 | 
2025-10-26 00:20:03.119014 | PLAY [controller]
2025-10-26 00:20:03.137983 | 
2025-10-26 00:20:03.138074 | TASK [Create the /root directory]
2025-10-26 00:20:04.033455 | controller | ok
2025-10-26 00:20:04.047193 | 
2025-10-26 00:20:04.047368 | TASK [Install glibc-langpack-en]
2025-10-26 00:20:12.093970 | controller | ok: Nothing to do
2025-10-26 00:20:12.105908 | 
2025-10-26 00:20:12.106054 | TASK [Ensure controller directory exists]
2025-10-26 00:20:12.538019 | controller | changed
2025-10-26 00:20:12.544847 | 
2025-10-26 00:20:12.544996 | TASK [Install container runtime]
2025-10-26 00:20:12.596915 | controller | ok
2025-10-26 00:20:12.638586 | 
2025-10-26 00:20:12.638749 | LOOP [ensure-podman : Find distribution installation]
2025-10-26 00:20:12.664194 | controller | ok: "/var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-26 00:20:12.672989 | controller | included: /var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-26 00:20:12.680497 | 
2025-10-26 00:20:12.680597 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-26 00:21:30.663021 | controller | changed
2025-10-26 00:21:30.677606 | 
2025-10-26 00:21:30.677823 | TASK [ensure-podman : Fetch podman version]
2025-10-26 00:21:31.429150 | controller | Client:       Podman Engine
2025-10-26 00:21:31.429228 | controller | Version:      4.6.2
2025-10-26 00:21:31.429259 | controller | API Version:  4.6.2
2025-10-26 00:21:31.429285 | controller | Go Version:   go1.19.12
2025-10-26 00:21:31.429322 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-26 00:21:31.429349 | controller | OS/Arch:      linux/amd64
2025-10-26 00:21:31.825842 | controller | ok: Runtime: 0:00:00.223926
2025-10-26 00:21:31.835971 | 
2025-10-26 00:21:31.836120 | TASK [ensure-podman : Print podman version installed]
2025-10-26 00:21:31.872842 | Podman version: Client:       Podman Engine
2025-10-26 00:21:31.873077 | Version:      4.6.2
2025-10-26 00:21:31.873130 | API Version:  4.6.2
2025-10-26 00:21:31.873163 | Go Version:   go1.19.12
2025-10-26 00:21:31.873190 | Built:        Mon Aug 28 19:38:31 2023
2025-10-26 00:21:31.873216 | OS/Arch:      linux/amd64
2025-10-26 00:21:31.882703 | 
2025-10-26 00:21:31.882824 | TASK [ensure-podman : Validate podman engine]
2025-10-26 00:21:32.043998 | controller | skipping: Conditional result was False
2025-10-26 00:21:32.051547 | 
2025-10-26 00:21:32.051684 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-26 00:21:32.076605 | controller | skipping: Conditional result was False
2025-10-26 00:21:32.089037 | 
2025-10-26 00:21:32.089135 | TASK [Ensure python3.8 is present]
2025-10-26 00:21:32.113886 | controller | skipping: Conditional result was False
2025-10-26 00:21:32.120229 | 
2025-10-26 00:21:32.120298 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-26 00:21:32.141216 | controller | ok
2025-10-26 00:21:32.162891 | 
2025-10-26 00:21:32.163018 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-26 00:21:35.867753 | controller | ok: Nothing to do
2025-10-26 00:21:35.881495 | 
2025-10-26 00:21:35.881652 | TASK [our-ensure-python : Also install python3-devel]
2025-10-26 00:21:49.317865 | controller | changed
2025-10-26 00:21:49.345089 | 
2025-10-26 00:21:49.345281 | TASK [Run ensure-virtualenv role]
2025-10-26 00:21:49.371799 | controller | ok
2025-10-26 00:21:49.400623 | 
2025-10-26 00:21:49.400754 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-26 00:21:49.799588 | controller | /usr/bin/virtualenv
2025-10-26 00:21:50.042820 | controller | ok: Runtime: 0:00:00.005015
2025-10-26 00:21:50.056039 | 
2025-10-26 00:21:50.056174 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-26 00:21:50.095334 | controller | skipping: Conditional result was False
2025-10-26 00:21:50.095908 | controller | ok: All items complete
2025-10-26 00:21:50.095995 | 
2025-10-26 00:21:50.133260 | 
2025-10-26 00:21:50.133467 | TASK [Find the full path of the Python interpreter]
2025-10-26 00:21:50.590334 | controller | /usr/bin/python3
2025-10-26 00:21:50.783101 | controller | ok
2025-10-26 00:21:50.790622 | 
2025-10-26 00:21:50.790749 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-26 00:21:52.317341 | controller | created virtual environment CPython3.11.0.final.0-64 in 812ms
2025-10-26 00:21:52.358997 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-26 00:21:52.359051 | 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-26 00:21:52.359066 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-26 00:21:52.359089 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-26 00:21:52.457149 | controller | changed
2025-10-26 00:21:52.468861 | 
2025-10-26 00:21:52.468993 | TASK [Set selinux package]
2025-10-26 00:21:52.496334 | controller | ok
2025-10-26 00:21:52.506872 | 
2025-10-26 00:21:52.507009 | TASK [Set selinux package (Fedora)]
2025-10-26 00:21:52.543982 | controller | ok
2025-10-26 00:21:52.555814 | 
2025-10-26 00:21:52.555945 | TASK [Install selinux into virtualenv]
2025-10-26 00:21:55.208877 | controller | Collecting selinux-please-lie-to-me
2025-10-26 00:21:55.297575 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-26 00:21:55.823214 | controller | Collecting setuptools<50.0.0
2025-10-26 00:21:55.837665 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-26 00:21:55.931147 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 9.1 MB/s eta 0:00:00
2025-10-26 00:21:56.083484 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-26 00:21:56.083801 | controller |   Attempting uninstall: setuptools
2025-10-26 00:21:56.088663 | controller |     Found existing installation: setuptools 62.6.0
2025-10-26 00:21:56.201241 | controller |     Uninstalling setuptools-62.6.0:
2025-10-26 00:21:56.216038 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-26 00:21:56.973216 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-26 00:21:57.177232 | controller |
2025-10-26 00:21:57.387170 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-26 00:21:57.387215 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-26 00:21:57.714755 | controller | ok: Runtime: 0:00:04.328575
2025-10-26 00:21:57.731548 | 
2025-10-26 00:21:57.731806 | TASK [Install pytest-forked into virtualenv]
2025-10-26 00:21:58.936137 | controller | Collecting pytest-forked
2025-10-26 00:21:59.022122 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-26 00:21:59.079315 | controller | Collecting py
2025-10-26 00:21:59.095729 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-26 00:21:59.127990 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.5 MB/s eta 0:00:00
2025-10-26 00:21:59.300826 | controller | Collecting pytest>=3.10
2025-10-26 00:21:59.313012 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-26 00:21:59.361502 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.0 MB/s eta 0:00:00
2025-10-26 00:21:59.415296 | controller | Collecting iniconfig>=1
2025-10-26 00:21:59.449908 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-26 00:21:59.514814 | controller | Collecting packaging>=20
2025-10-26 00:21:59.527380 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-26 00:21:59.537918 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.4 MB/s eta 0:00:00
2025-10-26 00:21:59.584146 | controller | Collecting pluggy<2,>=1.5
2025-10-26 00:21:59.598649 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-26 00:21:59.671952 | controller | Collecting pygments>=2.7.2
2025-10-26 00:21:59.686180 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-26 00:21:59.775444 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 14.3 MB/s eta 0:00:00
2025-10-26 00:21:59.906436 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-26 00:22:02.173238 | 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-26 00:22:02.191210 | controller |
2025-10-26 00:22:02.385561 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-26 00:22:02.385613 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-26 00:22:02.901319 | controller | ok: Runtime: 0:00:04.170037
2025-10-26 00:22:02.915835 | 
2025-10-26 00:22:02.916085 | TASK [Update pip]
2025-10-26 00:22:04.093634 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-26 00:22:04.381414 | controller | Collecting pip
2025-10-26 00:22:04.482878 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-26 00:22:04.690992 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.7 MB/s eta 0:00:00
2025-10-26 00:22:04.813617 | controller | Installing collected packages: pip
2025-10-26 00:22:04.814077 | controller |   Attempting uninstall: pip
2025-10-26 00:22:04.818580 | controller |     Found existing installation: pip 22.2.2
2025-10-26 00:22:05.109743 | controller |     Uninstalling pip-22.2.2:
2025-10-26 00:22:05.139802 | controller |       Successfully uninstalled pip-22.2.2
2025-10-26 00:22:06.914016 | controller | Successfully installed pip-25.3
2025-10-26 00:22:07.609200 | controller | ok: Runtime: 0:00:03.702941
2025-10-26 00:22:07.623178 | 
2025-10-26 00:22:07.623384 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-26 00:22:08.205253 | controller | changed
2025-10-26 00:22:08.217659 | 
2025-10-26 00:22:08.217828 | TASK [Install ansible into virtualenv]
2025-10-26 00:22:09.308294 | controller | Processing ./src/github.com/ansible/ansible
2025-10-26 00:22:09.314668 | controller |   Installing build dependencies: started
2025-10-26 00:22:11.207629 | controller |   Installing build dependencies: finished with status 'done'
2025-10-26 00:22:12.807763 | controller |   Getting requirements to build wheel: started
2025-10-26 00:22:12.807828 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-26 00:22:13.734762 | controller |   Preparing metadata (pyproject.toml): started
2025-10-26 00:22:13.734817 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-26 00:22:13.738121 | 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-26 00:22:13.743014 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-26 00:22:14.383780 | controller | ERROR
2025-10-26 00:22:14.384032 | controller | {
2025-10-26 00:22:14.384076 | controller |   "delta": "0:00:05.189425",
2025-10-26 00:22:14.384102 | controller |   "end": "2025-10-26 00:22:13.888568",
2025-10-26 00:22:14.384125 | controller |   "msg": "non-zero return code",
2025-10-26 00:22:14.384161 | controller |   "rc": 1,
2025-10-26 00:22:14.384185 | controller |   "start": "2025-10-26 00:22:08.699143"
2025-10-26 00:22:14.384206 | controller | }
failure
2025-10-26 00:22:14.386943 | 
2025-10-26 00:22:14.387022 | PLAY RECAP
2025-10-26 00:22:14.387089 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-26 00:22:14.387126 | 
2025-10-26 00:22:14.532621 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-26 00:22:14.534808 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-26 00:22:15.164182 | 
2025-10-26 00:22:15.164333 | PLAY [all]
2025-10-26 00:22:15.187637 | 
2025-10-26 00:22:15.187790 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-26 00:22:16.008269 | controller | changed: non-zero return code
2025-10-26 00:22:16.020899 | 
2025-10-26 00:22:16.021120 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-26 00:22:16.049649 | controller | skipping: Conditional result was False
2025-10-26 00:22:16.064497 | 
2025-10-26 00:22:16.064741 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-26 00:22:16.111590 | 
2025-10-26 00:22:16.111932 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-26 00:22:16.153073 | 
2025-10-26 00:22:16.153461 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-26 00:22:16.181602 | controller | skipping: Conditional result was False
2025-10-26 00:22:16.199179 | 
2025-10-26 00:22:16.199408 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-26 00:22:16.237478 | 
2025-10-26 00:22:16.237729 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-26 00:22:16.263801 | controller | skipping: Conditional result was False
2025-10-26 00:22:16.273309 | 
2025-10-26 00:22:16.273425 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-26 00:22:16.298813 | controller | skipping: Conditional result was False
2025-10-26 00:22:16.308973 | 
2025-10-26 00:22:16.309103 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-26 00:22:16.338113 | controller | skipping: Conditional result was False
2025-10-26 00:22:16.375264 | 
2025-10-26 00:22:16.375392 | PLAY RECAP
2025-10-26 00:22:16.375433 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-26 00:22:16.375452 | 
2025-10-26 00:22:16.521098 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-26 00:22:16.522106 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-26 00:22:17.146380 | 
2025-10-26 00:22:17.146505 | PLAY [all:!appliance*]
2025-10-26 00:22:17.167970 | 
2025-10-26 00:22:17.168069 | TASK [unregister the node]
2025-10-26 00:22:17.311747 | controller | skipping: Conditional result was False
2025-10-26 00:22:17.327622 | 
2025-10-26 00:22:17.327985 | TASK [include_role : fetch-output]
2025-10-26 00:22:17.383655 | controller | ok
2025-10-26 00:22:17.403099 | 
2025-10-26 00:22:17.403218 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-26 00:22:17.458500 | controller | skipping: Conditional result was False
2025-10-26 00:22:17.467404 | 
2025-10-26 00:22:17.467506 | TASK [fetch-output : Set log path for single node]
2025-10-26 00:22:17.499622 | controller | ok
2025-10-26 00:22:17.507461 | 
2025-10-26 00:22:17.507556 | LOOP [fetch-output : Ensure local output dirs]
2025-10-26 00:22:17.926636 | controller -> localhost | ok: "/var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/logs"
2025-10-26 00:22:18.233578 | controller -> localhost | changed: "/var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/artifacts"
2025-10-26 00:22:18.486279 | controller -> localhost | changed: "/var/lib/zuul/builds/3df9c94bbbd6429bb11b638bdf0c4ea1/work/docs"
2025-10-26 00:22:18.498586 | 
2025-10-26 00:22:18.498684 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-26 00:22:19.712533 | controller | changed:
2025-10-26 00:22:19.713113 | controller | .d..t...... ./
2025-10-26 00:22:19.713191 | controller | cd+++++++++ controller/
2025-10-26 00:22:19.713268 | controller | changed: All items complete
2025-10-26 00:22:19.713316 | 
2025-10-26 00:22:20.785251 | controller | changed: .d..t...... ./
2025-10-26 00:22:21.860988 | controller | changed: .d..t...... ./
2025-10-26 00:22:21.892423 | 
2025-10-26 00:22:21.892698 | TASK [include_role : fetch-output-openshift]
2025-10-26 00:22:21.930389 | controller | skipping: Conditional result was False
2025-10-26 00:22:21.939373 | 
2025-10-26 00:22:21.939470 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-26 00:22:21.982740 | controller | skipping: Conditional result was False
2025-10-26 00:22:21.996985 | controller | skipping: Conditional result was False
2025-10-26 00:22:22.044604 | 
2025-10-26 00:22:22.044830 | PLAY [localhost]
2025-10-26 00:22:22.057626 | 
2025-10-26 00:22:22.057740 | TASK [Run Zuul manifest role]
2025-10-26 00:22:22.077349 | localhost | ok
2025-10-26 00:22:22.091090 | 
2025-10-26 00:22:22.091199 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-26 00:22:22.488641 | localhost | changed
2025-10-26 00:22:22.503620 | 
2025-10-26 00:22:22.503846 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-26 00:22:22.539106 | localhost | ok
2025-10-26 00:22:22.547626 | 
2025-10-26 00:22:22.547723 | TASK [Set zuul-log-path fact]
2025-10-26 00:22:22.577101 | localhost | ok
2025-10-26 00:22:22.590901 | 
2025-10-26 00:22:22.590972 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-26 00:22:22.620781 | localhost | ok
2025-10-26 00:22:22.630314 | 
2025-10-26 00:22:22.630383 | LOOP [Run upload-logs-swift role]
2025-10-26 00:22:22.656594 | localhost | Output suppressed because no_log was given
2025-10-26 00:22:22.681288 | 
2025-10-26 00:22:22.681357 | TASK [Set zuul-log-path fact]
2025-10-26 00:22:22.716808 | localhost | skipping: Conditional result was False
2025-10-26 00:22:22.722094 | 
2025-10-26 00:22:22.722164 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-26 00:22:23.209191 | localhost -> localhost | ok: Runtime: 0:00:00.010090
2025-10-26 00:22:23.217931 | 
2025-10-26 00:22:23.218045 | TASK [upload-logs-swift : Upload logs to swift]