2025-10-13 00:06:35.839786 | Job console starting...
2025-10-13 00:06:35.859663 | Updating repositories
2025-10-13 00:06:35.985341 | Preparing job workspace
2025-10-13 00:06:39.909100 | Running Ansible setup...
2025-10-13 00:06:46.002361 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:06:46.642522 | 
2025-10-13 00:06:46.642697 | PLAY [localhost]
2025-10-13 00:06:46.652340 | 
2025-10-13 00:06:46.652455 | TASK [Gathering Facts]
2025-10-13 00:06:47.750393 | localhost | ok
2025-10-13 00:06:47.763431 | 
2025-10-13 00:06:47.763565 | TASK [Setup log path fact]
2025-10-13 00:06:47.782193 | localhost | ok
2025-10-13 00:06:47.810186 | 
2025-10-13 00:06:47.810297 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:06:47.878911 | localhost | ok
2025-10-13 00:06:47.897884 | 
2025-10-13 00:06:47.898017 | TASK [emit-job-header : Print job information]
2025-10-13 00:06:47.956374 | # Job Information
2025-10-13 00:06:47.956538 | Ansible Version: 2.15.12
2025-10-13 00:06:47.956570 | Job: ansible-test-sanity-docker-milestone
2025-10-13 00:06:47.956592 | Pipeline: periodic
2025-10-13 00:06:47.956610 | Executor: ze04.softwarefactory-project.io
2025-10-13 00:06:47.956629 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-13 00:06:47.956651 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/45e/ansible/45e942a97a744b8d86346662424453aa/
2025-10-13 00:06:47.956671 | Event ID: 5c3858b4bf9e4fdab660facb3b50ba54
2025-10-13 00:06:47.960731 | 
2025-10-13 00:06:47.960805 | LOOP [emit-job-header : Print node information]
2025-10-13 00:06:48.051485 | localhost | ok:
2025-10-13 00:06:48.051642 | localhost | # Node Information
2025-10-13 00:06:48.051669 | localhost | Inventory Hostname: controller
2025-10-13 00:06:48.051718 | localhost | Hostname: ip-172-16-47-65
2025-10-13 00:06:48.051739 | localhost | Username: zuul-worker
2025-10-13 00:06:48.051760 | localhost | Distro: Fedora 37
2025-10-13 00:06:48.051778 | localhost | Provider: ansible-us-east-2
2025-10-13 00:06:48.051796 | localhost | Region: us-east-2
2025-10-13 00:06:48.051813 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-13 00:06:48.051830 | localhost | Product Name: t3.small
2025-10-13 00:06:48.051847 | localhost | Interface IP: 18.117.126.243
2025-10-13 00:06:48.063791 | 
2025-10-13 00:06:48.063881 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 00:06:48.448267 | localhost -> localhost | changed
2025-10-13 00:06:48.453579 | 
2025-10-13 00:06:48.453721 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 00:06:49.379704 | localhost -> localhost | changed
2025-10-13 00:06:49.400202 | 
2025-10-13 00:06:49.400271 | PLAY [all:!appliance*]
2025-10-13 00:06:49.416405 | 
2025-10-13 00:06:49.416477 | TASK [include_role : start-zuul-console]
2025-10-13 00:06:49.436227 | controller | ok
2025-10-13 00:06:49.451217 | 
2025-10-13 00:06:49.451289 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 00:06:50.269190 | controller | ok
2025-10-13 00:06:50.294842 | 
2025-10-13 00:06:50.295004 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-13 00:06:51.801831 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-13 00:06:51.809040 | 
2025-10-13 00:06:51.809104 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-13 00:06:51.962190 | controller | skipping: Conditional result was False
2025-10-13 00:06:51.968836 | 
2025-10-13 00:06:51.968912 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-13 00:06:52.003635 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.010820 | 
2025-10-13 00:06:52.010913 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-13 00:06:52.036171 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.043578 | 
2025-10-13 00:06:52.043700 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-13 00:06:52.074962 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.081773 | 
2025-10-13 00:06:52.081852 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-13 00:06:52.109506 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.116505 | 
2025-10-13 00:06:52.116575 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-13 00:06:52.141067 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.161556 | 
2025-10-13 00:06:52.161753 | TASK [Disable Fedora Modular]
2025-10-13 00:06:52.893154 | controller | changed
2025-10-13 00:06:52.905392 | 
2025-10-13 00:06:52.905532 | TASK [Enable EPEL]
2025-10-13 00:06:52.933174 | controller | skipping: Conditional result was False
2025-10-13 00:06:52.948007 | 
2025-10-13 00:06:52.948231 | TASK [Register the RHEL node]
2025-10-13 00:06:53.140017 | 
2025-10-13 00:06:53.140299 | TASK [Show the subscription-manager status]
2025-10-13 00:06:53.336885 | controller | skipping: Conditional result was False
2025-10-13 00:06:53.351521 | 
2025-10-13 00:06:53.351672 | TASK [Enable EPEL on RHEL]
2025-10-13 00:06:53.513023 | controller | skipping: Conditional result was False
2025-10-13 00:06:53.525723 | 
2025-10-13 00:06:53.525893 | TASK [Install git and tox]
2025-10-13 00:08:27.717470 | controller | changed
2025-10-13 00:08:27.744584 | 
2025-10-13 00:08:27.744732 | TASK [include_role : prepare-workspace]
2025-10-13 00:08:27.778750 | controller | ok
2025-10-13 00:08:27.807398 | 
2025-10-13 00:08:27.807526 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 00:08:28.312067 | controller | ok
2025-10-13 00:08:28.328103 | 
2025-10-13 00:08:28.328482 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 00:08:41.835066 | controller | Output suppressed because no_log was given
2025-10-13 00:08:41.851071 | 
2025-10-13 00:08:41.851186 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 00:08:41.880457 | controller | skipping: Conditional result was False
2025-10-13 00:08:41.902386 | 
2025-10-13 00:08:41.902462 | PLAY [all:!appliance]
2025-10-13 00:08:41.917614 | 
2025-10-13 00:08:41.917716 | TASK [Run add-build-sshkey role (RSA)]
2025-10-13 00:08:41.937948 | controller | ok
2025-10-13 00:08:41.975734 | 
2025-10-13 00:08:41.975855 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:08:42.233890 | controller -> localhost | ok
2025-10-13 00:08:42.247826 | 
2025-10-13 00:08:42.247960 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:08:42.279425 | controller | ok
2025-10-13 00:08:42.305148 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:08:42.313937 | 
2025-10-13 00:08:42.314028 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:08:42.962852 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 00:08:42.963142 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_rsa.
2025-10-13 00:08:42.963184 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_rsa.pub.
2025-10-13 00:08:42.963223 | controller -> localhost | The key fingerprint is:
2025-10-13 00:08:42.963251 | controller -> localhost | SHA256:fPZMtCrbtJ+3kbHZcGmUSUM/+jnUL+207fReCSY5lao zuul-build-sshkey
2025-10-13 00:08:42.963277 | controller -> localhost | The key's randomart image is:
2025-10-13 00:08:42.963302 | controller -> localhost | +---[RSA 2048]----+
2025-10-13 00:08:42.963327 | controller -> localhost | |              .+ |
2025-10-13 00:08:42.963353 | controller -> localhost | |              o =|
2025-10-13 00:08:42.963377 | controller -> localhost | |            .o =.|
2025-10-13 00:08:42.963401 | controller -> localhost | |       .   .+.o +|
2025-10-13 00:08:42.963431 | controller -> localhost | |        S o=o+o+o|
2025-10-13 00:08:42.963482 | controller -> localhost | |         o.=+ =X+|
2025-10-13 00:08:42.963532 | controller -> localhost | |        .Eo o *=B|
2025-10-13 00:08:42.963572 | controller -> localhost | |         = . ..**|
2025-10-13 00:08:42.963610 | controller -> localhost | |        . o.o..=*|
2025-10-13 00:08:42.963646 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:08:42.963745 | controller -> localhost | ok: Runtime: 0:00:00.188167
2025-10-13 00:08:42.972168 | 
2025-10-13 00:08:42.972261 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:08:43.010500 | controller | ok
2025-10-13 00:08:43.034160 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:08:43.050225 | 
2025-10-13 00:08:43.050337 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:08:43.076150 | controller | skipping: Conditional result was False
2025-10-13 00:08:43.090810 | 
2025-10-13 00:08:43.090945 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:08:43.827574 | controller | changed
2025-10-13 00:08:43.840948 | 
2025-10-13 00:08:43.841096 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:08:44.214772 | controller | ok
2025-10-13 00:08:44.223457 | 
2025-10-13 00:08:44.223625 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:08:46.161634 | controller | changed
2025-10-13 00:08:46.169741 | 
2025-10-13 00:08:46.169854 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:08:47.510600 | controller | changed
2025-10-13 00:08:47.523882 | 
2025-10-13 00:08:47.524027 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:08:47.552173 | controller | skipping: Conditional result was False
2025-10-13 00:08:47.565998 | 
2025-10-13 00:08:47.566140 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:08:47.984153 | controller -> localhost | changed
2025-10-13 00:08:48.015156 | 
2025-10-13 00:08:48.015327 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:08:48.327508 | controller -> localhost | Identity added: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_rsa (zuul-build-sshkey)
2025-10-13 00:08:48.327724 | controller -> localhost | ok: Runtime: 0:00:00.007179
2025-10-13 00:08:48.334549 | 
2025-10-13 00:08:48.334637 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:08:48.889127 | controller | ok
2025-10-13 00:08:48.902565 | 
2025-10-13 00:08:48.902780 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:08:48.940512 | controller | skipping: Conditional result was False
2025-10-13 00:08:48.972492 | 
2025-10-13 00:08:48.972653 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-13 00:08:48.998423 | controller | ok
2025-10-13 00:08:49.025227 | 
2025-10-13 00:08:49.025340 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 00:08:49.274849 | controller -> localhost | ok
2025-10-13 00:08:49.289834 | 
2025-10-13 00:08:49.289979 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 00:08:49.330833 | controller | ok
2025-10-13 00:08:49.354730 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 00:08:49.363063 | 
2025-10-13 00:08:49.363152 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 00:08:49.672956 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-13 00:08:49.673140 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_ecdsa.
2025-10-13 00:08:49.673172 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_ecdsa.pub.
2025-10-13 00:08:49.673209 | controller -> localhost | The key fingerprint is:
2025-10-13 00:08:49.673230 | controller -> localhost | SHA256:HK8oCxF2qs/ZV34CC4MQyXWpylOp//mD/oO5Tn6+Vrs zuul-build-sshkey
2025-10-13 00:08:49.673252 | controller -> localhost | The key's randomart image is:
2025-10-13 00:08:49.673279 | controller -> localhost | +---[ECDSA 521]---+
2025-10-13 00:08:49.673302 | controller -> localhost | |.... ..          |
2025-10-13 00:08:49.673323 | controller -> localhost | |o.  ..           |
2025-10-13 00:08:49.673345 | controller -> localhost | | .o +   .        |
2025-10-13 00:08:49.673370 | controller -> localhost | |.. B   . o       |
2025-10-13 00:08:49.673394 | controller -> localhost | |..*.    S .      |
2025-10-13 00:08:49.673413 | controller -> localhost | | *..o ...o       |
2025-10-13 00:08:49.673430 | controller -> localhost | |. + .+==o .      |
2025-10-13 00:08:49.673448 | controller -> localhost | | o =o*+=o..      |
2025-10-13 00:08:49.673465 | controller -> localhost | |  + *OB=+E.      |
2025-10-13 00:08:49.673483 | controller -> localhost | +----[SHA256]-----+
2025-10-13 00:08:49.673528 | controller -> localhost | ok: Runtime: 0:00:00.010469
2025-10-13 00:08:49.680368 | 
2025-10-13 00:08:49.680432 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 00:08:49.711883 | controller | ok
2025-10-13 00:08:49.720406 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 00:08:49.729605 | 
2025-10-13 00:08:49.729668 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 00:08:49.753925 | controller | skipping: Conditional result was False
2025-10-13 00:08:49.760519 | 
2025-10-13 00:08:49.760584 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 00:08:50.494185 | controller | changed
2025-10-13 00:08:50.500403 | 
2025-10-13 00:08:50.500481 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 00:08:50.837208 | controller | ok
2025-10-13 00:08:50.843089 | 
2025-10-13 00:08:50.843158 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 00:08:52.287449 | controller | changed
2025-10-13 00:08:52.301885 | 
2025-10-13 00:08:52.302060 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 00:08:54.911188 | controller | changed
2025-10-13 00:08:54.920970 | 
2025-10-13 00:08:54.921122 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 00:08:54.937515 | controller | skipping: Conditional result was False
2025-10-13 00:08:54.949168 | 
2025-10-13 00:08:54.949334 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 00:08:55.196128 | controller -> localhost | changed
2025-10-13 00:08:55.221566 | 
2025-10-13 00:08:55.221807 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 00:08:55.556057 | controller -> localhost | Identity added: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/45e942a97a744b8d86346662424453aa_id_ecdsa (zuul-build-sshkey)
2025-10-13 00:08:55.556307 | controller -> localhost | ok: Runtime: 0:00:00.022718
2025-10-13 00:08:55.563127 | 
2025-10-13 00:08:55.563194 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 00:08:55.918708 | controller | ok
2025-10-13 00:08:55.925550 | 
2025-10-13 00:08:55.925636 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 00:08:55.991530 | controller | skipping: Conditional result was False
2025-10-13 00:08:56.035635 | 
2025-10-13 00:08:56.035765 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 00:08:56.049551 | controller | skipping: Conditional result was False
2025-10-13 00:08:56.056490 | 
2025-10-13 00:08:56.056596 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 00:08:56.369901 | controller | ok: "logs"
2025-10-13 00:08:56.370288 | controller | ok: All items complete
2025-10-13 00:08:56.370341 | 
2025-10-13 00:08:56.653107 | controller | ok: "artifacts"
2025-10-13 00:08:56.967054 | controller | ok: "docs"
2025-10-13 00:08:56.987214 | 
2025-10-13 00:08:56.987346 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 00:08:57.568329 | controller | changed: "logs"
2025-10-13 00:08:57.857877 | controller | changed: "artifacts"
2025-10-13 00:08:58.154245 | controller | changed: "docs"
2025-10-13 00:08:58.187227 | 
2025-10-13 00:08:58.187316 | PLAY RECAP
2025-10-13 00:08:58.187356 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-13 00:08:58.187383 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 00:08:58.187402 | 
2025-10-13 00:08:58.293788 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-13 00:08:58.294883 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:08:58.879990 | 
2025-10-13 00:08:58.880162 | PLAY [all]
2025-10-13 00:08:58.902894 | 
2025-10-13 00:08:58.903027 | TASK [Install binary dependencies]
2025-10-13 00:08:58.952972 | controller | ok
2025-10-13 00:08:58.973780 | 
2025-10-13 00:08:58.973905 | TASK [bindep : Include find tasks]
2025-10-13 00:08:59.004856 | controller | ok
2025-10-13 00:08:59.014437 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 00:08:59.021191 | 
2025-10-13 00:08:59.021263 | TASK [bindep : Look for bindep.txt]
2025-10-13 00:08:59.570895 | controller | ok
2025-10-13 00:08:59.585152 | 
2025-10-13 00:08:59.585328 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:08:59.613382 | controller | skipping: Conditional result was False
2025-10-13 00:08:59.627158 | 
2025-10-13 00:08:59.627333 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 00:08:59.938475 | controller | ok
2025-10-13 00:08:59.945865 | 
2025-10-13 00:08:59.945958 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:08:59.969998 | controller | skipping: Conditional result was False
2025-10-13 00:08:59.976131 | 
2025-10-13 00:08:59.976208 | TASK [bindep : Look for bindep fallback file]
2025-10-13 00:08:59.999947 | controller | skipping: Conditional result was False
2025-10-13 00:09:00.006604 | 
2025-10-13 00:09:00.006719 | TASK [bindep : Define bindep_file fact]
2025-10-13 00:09:00.030403 | controller | skipping: Conditional result was False
2025-10-13 00:09:00.037099 | 
2025-10-13 00:09:00.037193 | TASK [bindep : Include bindep tasks]
2025-10-13 00:09:00.061644 | controller | skipping: Conditional result was False
2025-10-13 00:09:00.073247 | 
2025-10-13 00:09:00.073341 | TASK [bindep : Include install tasks]
2025-10-13 00:09:00.098098 | controller | skipping: Conditional result was False
2025-10-13 00:09:00.105957 | 
2025-10-13 00:09:00.106046 | LOOP [bindep : Include package tasks]
2025-10-13 00:09:00.169546 | 
2025-10-13 00:09:00.169852 | TASK [Run test-setup role]
2025-10-13 00:09:00.194329 | controller | ok
2025-10-13 00:09:00.220947 | 
2025-10-13 00:09:00.221108 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 00:09:00.532972 | controller | ok
2025-10-13 00:09:00.546030 | 
2025-10-13 00:09:00.546161 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 00:09:00.711382 | controller | skipping: Conditional result was False
2025-10-13 00:09:00.766915 | 
2025-10-13 00:09:00.767091 | PLAY RECAP
2025-10-13 00:09:00.767157 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:09:00.767188 | 
2025-10-13 00:09:00.869819 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 00:09:00.871299 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:09:01.455862 | 
2025-10-13 00:09:01.456034 | PLAY [controller]
2025-10-13 00:09:01.477131 | 
2025-10-13 00:09:01.477250 | TASK [Create the /root directory]
2025-10-13 00:09:02.524421 | controller | ok
2025-10-13 00:09:02.538961 | 
2025-10-13 00:09:02.539159 | TASK [Install glibc-langpack-en]
2025-10-13 00:09:10.997288 | controller | ok: Nothing to do
2025-10-13 00:09:11.007781 | 
2025-10-13 00:09:11.007914 | TASK [Ensure controller directory exists]
2025-10-13 00:09:11.430880 | controller | changed
2025-10-13 00:09:11.444990 | 
2025-10-13 00:09:11.445264 | TASK [Install container runtime]
2025-10-13 00:09:11.525338 | controller | ok
2025-10-13 00:09:11.585354 | 
2025-10-13 00:09:11.585495 | LOOP [ensure-podman : Find distribution installation]
2025-10-13 00:09:11.609000 | controller | ok: "/var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-13 00:09:11.620152 | controller | included: /var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-13 00:09:11.630083 | 
2025-10-13 00:09:11.630203 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-13 00:10:39.149142 | controller | changed
2025-10-13 00:10:39.165469 | 
2025-10-13 00:10:39.165716 | TASK [ensure-podman : Fetch podman version]
2025-10-13 00:10:39.887150 | controller | Client:       Podman Engine
2025-10-13 00:10:39.917164 | controller | Version:      4.6.2
2025-10-13 00:10:39.917216 | controller | API Version:  4.6.2
2025-10-13 00:10:39.917226 | controller | Go Version:   go1.19.12
2025-10-13 00:10:39.917251 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:10:39.917261 | controller | OS/Arch:      linux/amd64
2025-10-13 00:10:40.322564 | controller | ok: Runtime: 0:00:00.196280
2025-10-13 00:10:40.336125 | 
2025-10-13 00:10:40.336282 | TASK [ensure-podman : Print podman version installed]
2025-10-13 00:10:40.369461 | Podman version: Client:       Podman Engine
2025-10-13 00:10:40.369617 | Version:      4.6.2
2025-10-13 00:10:40.369645 | API Version:  4.6.2
2025-10-13 00:10:40.369666 | Go Version:   go1.19.12
2025-10-13 00:10:40.369702 | Built:        Mon Aug 28 19:38:31 2023
2025-10-13 00:10:40.369723 | OS/Arch:      linux/amd64
2025-10-13 00:10:40.375141 | 
2025-10-13 00:10:40.375201 | TASK [ensure-podman : Validate podman engine]
2025-10-13 00:10:40.501238 | controller | skipping: Conditional result was False
2025-10-13 00:10:40.509912 | 
2025-10-13 00:10:40.510006 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-13 00:10:40.525398 | controller | skipping: Conditional result was False
2025-10-13 00:10:40.548500 | 
2025-10-13 00:10:40.548630 | TASK [Ensure python3.8 is present]
2025-10-13 00:10:40.563883 | controller | skipping: Conditional result was False
2025-10-13 00:10:40.572486 | 
2025-10-13 00:10:40.572577 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-13 00:10:40.594530 | controller | ok
2025-10-13 00:10:40.622343 | 
2025-10-13 00:10:40.622464 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-13 00:10:44.449064 | controller | ok: Nothing to do
2025-10-13 00:10:44.463268 | 
2025-10-13 00:10:44.463446 | TASK [our-ensure-python : Also install python3-devel]
2025-10-13 00:10:58.622639 | controller | changed
2025-10-13 00:10:58.637980 | 
2025-10-13 00:10:58.638095 | TASK [Run ensure-virtualenv role]
2025-10-13 00:10:58.672509 | controller | ok
2025-10-13 00:10:58.704136 | 
2025-10-13 00:10:58.704294 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-13 00:10:59.105014 | controller | /usr/bin/virtualenv
2025-10-13 00:10:59.345014 | controller | ok: Runtime: 0:00:00.004593
2025-10-13 00:10:59.357807 | 
2025-10-13 00:10:59.357966 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-13 00:10:59.379731 | controller | skipping: Conditional result was False
2025-10-13 00:10:59.380194 | controller | ok: All items complete
2025-10-13 00:10:59.380222 | 
2025-10-13 00:10:59.445419 | 
2025-10-13 00:10:59.445579 | TASK [Find the full path of the Python interpreter]
2025-10-13 00:10:59.872311 | controller | /usr/bin/python3
2025-10-13 00:11:00.075197 | controller | ok
2025-10-13 00:11:00.086985 | 
2025-10-13 00:11:00.087126 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-13 00:11:01.520584 | controller | created virtual environment CPython3.11.0.final.0-64 in 774ms
2025-10-13 00:11:01.567152 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-13 00:11:01.567212 | 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-13 00:11:01.567228 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-13 00:11:01.567251 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-13 00:11:01.753490 | controller | changed
2025-10-13 00:11:01.762850 | 
2025-10-13 00:11:01.762949 | TASK [Set selinux package]
2025-10-13 00:11:01.795316 | controller | ok
2025-10-13 00:11:01.800576 | 
2025-10-13 00:11:01.800644 | TASK [Set selinux package (Fedora)]
2025-10-13 00:11:01.830752 | controller | ok
2025-10-13 00:11:01.835634 | 
2025-10-13 00:11:01.835724 | TASK [Install selinux into virtualenv]
2025-10-13 00:11:04.640009 | controller | Collecting selinux-please-lie-to-me
2025-10-13 00:11:04.737612 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-13 00:11:05.269026 | controller | Collecting setuptools<50.0.0
2025-10-13 00:11:05.286168 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-13 00:11:05.393409 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.8 MB/s eta 0:00:00
2025-10-13 00:11:05.548495 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-13 00:11:05.548910 | controller |   Attempting uninstall: setuptools
2025-10-13 00:11:05.553947 | controller |     Found existing installation: setuptools 62.6.0
2025-10-13 00:11:05.665939 | controller |     Uninstalling setuptools-62.6.0:
2025-10-13 00:11:05.681351 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-13 00:11:06.456213 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-13 00:11:06.662533 | controller |
2025-10-13 00:11:06.877969 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:11:06.878015 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:11:07.021272 | controller | ok: Runtime: 0:00:04.495245
2025-10-13 00:11:07.034120 | 
2025-10-13 00:11:07.034259 | TASK [Install pytest-forked into virtualenv]
2025-10-13 00:11:08.253508 | controller | Collecting pytest-forked
2025-10-13 00:11:08.339720 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-13 00:11:08.397693 | controller | Collecting py
2025-10-13 00:11:08.412697 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-13 00:11:08.445679 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-10-13 00:11:08.615308 | controller | Collecting pytest>=3.10
2025-10-13 00:11:08.627699 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-13 00:11:08.676237 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.0 MB/s eta 0:00:00
2025-10-13 00:11:08.730997 | controller | Collecting iniconfig>=1
2025-10-13 00:11:08.749702 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-13 00:11:08.816807 | controller | Collecting packaging>=20
2025-10-13 00:11:08.828293 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-13 00:11:08.838940 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.3 MB/s eta 0:00:00
2025-10-13 00:11:08.883893 | controller | Collecting pluggy<2,>=1.5
2025-10-13 00:11:08.896258 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-13 00:11:08.969364 | controller | Collecting pygments>=2.7.2
2025-10-13 00:11:08.981735 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-13 00:11:09.079384 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.0 MB/s eta 0:00:00
2025-10-13 00:11:09.208266 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-13 00:11:11.432278 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-13 00:11:11.448220 | controller |
2025-10-13 00:11:11.632376 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-13 00:11:11.632422 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-13 00:11:11.713073 | controller | ok: Runtime: 0:00:04.113734
2025-10-13 00:11:11.728014 | 
2025-10-13 00:11:11.728320 | TASK [Update pip]
2025-10-13 00:11:12.859313 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-13 00:11:13.130682 | controller | Collecting pip
2025-10-13 00:11:13.229468 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-13 00:11:13.396328 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.0 MB/s eta 0:00:00
2025-10-13 00:11:13.557587 | controller | Installing collected packages: pip
2025-10-13 00:11:13.557899 | controller |   Attempting uninstall: pip
2025-10-13 00:11:13.562345 | controller |     Found existing installation: pip 22.2.2
2025-10-13 00:11:13.821476 | controller |     Uninstalling pip-22.2.2:
2025-10-13 00:11:13.850830 | controller |       Successfully uninstalled pip-22.2.2
2025-10-13 00:11:15.593563 | controller | Successfully installed pip-25.2
2025-10-13 00:11:15.926329 | controller | ok: Runtime: 0:00:03.583525
2025-10-13 00:11:15.940481 | 
2025-10-13 00:11:15.940742 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-13 00:11:16.490502 | controller | changed
2025-10-13 00:11:16.499145 | 
2025-10-13 00:11:16.499266 | TASK [Install ansible into virtualenv]
2025-10-13 00:11:17.531784 | controller | Processing ./src/github.com/ansible/ansible
2025-10-13 00:11:17.538344 | controller |   Installing build dependencies: started
2025-10-13 00:11:19.544701 | controller |   Installing build dependencies: finished with status 'done'
2025-10-13 00:11:21.096829 | controller |   Getting requirements to build wheel: started
2025-10-13 00:11:21.096893 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-13 00:11:22.041887 | controller |   Preparing metadata (pyproject.toml): started
2025-10-13 00:11:22.041936 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-13 00:11:22.045028 | 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-13 00:11:22.049655 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-13 00:11:22.650985 | controller | ERROR
2025-10-13 00:11:22.651299 | controller | {
2025-10-13 00:11:22.651368 | controller |   "delta": "0:00:05.282705",
2025-10-13 00:11:22.651411 | controller |   "end": "2025-10-13 00:11:22.194927",
2025-10-13 00:11:22.651449 | controller |   "msg": "non-zero return code",
2025-10-13 00:11:22.651500 | controller |   "rc": 1,
2025-10-13 00:11:22.651536 | controller |   "start": "2025-10-13 00:11:16.912222"
2025-10-13 00:11:22.651572 | controller | }
failure
2025-10-13 00:11:22.654048 | 
2025-10-13 00:11:22.654143 | PLAY RECAP
2025-10-13 00:11:22.654223 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-13 00:11:22.654265 | 
2025-10-13 00:11:22.785996 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-13 00:11:22.789046 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:11:23.364461 | 
2025-10-13 00:11:23.364589 | PLAY [all]
2025-10-13 00:11:23.386585 | 
2025-10-13 00:11:23.386728 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 00:11:24.200105 | controller | changed: non-zero return code
2025-10-13 00:11:24.212813 | 
2025-10-13 00:11:24.213018 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 00:11:24.229205 | controller | skipping: Conditional result was False
2025-10-13 00:11:24.239969 | 
2025-10-13 00:11:24.240162 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 00:11:24.288090 | 
2025-10-13 00:11:24.288300 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 00:11:24.314652 | 
2025-10-13 00:11:24.314898 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 00:11:24.331164 | controller | skipping: Conditional result was False
2025-10-13 00:11:24.341820 | 
2025-10-13 00:11:24.341970 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 00:11:24.371775 | 
2025-10-13 00:11:24.372020 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 00:11:24.387704 | controller | skipping: Conditional result was False
2025-10-13 00:11:24.396708 | 
2025-10-13 00:11:24.396812 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 00:11:24.412397 | controller | skipping: Conditional result was False
2025-10-13 00:11:24.420993 | 
2025-10-13 00:11:24.421082 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 00:11:24.436038 | controller | skipping: Conditional result was False
2025-10-13 00:11:24.470498 | 
2025-10-13 00:11:24.470573 | PLAY RECAP
2025-10-13 00:11:24.470613 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 00:11:24.470632 | 
2025-10-13 00:11:24.565863 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 00:11:24.566760 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-13 00:11:25.209179 | 
2025-10-13 00:11:25.209370 | PLAY [all:!appliance*]
2025-10-13 00:11:25.232816 | 
2025-10-13 00:11:25.232931 | TASK [unregister the node]
2025-10-13 00:11:25.379826 | controller | skipping: Conditional result was False
2025-10-13 00:11:25.396491 | 
2025-10-13 00:11:25.396769 | TASK [include_role : fetch-output]
2025-10-13 00:11:25.442141 | controller | ok
2025-10-13 00:11:25.467309 | 
2025-10-13 00:11:25.467425 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 00:11:25.535000 | controller | skipping: Conditional result was False
2025-10-13 00:11:25.544813 | 
2025-10-13 00:11:25.544952 | TASK [fetch-output : Set log path for single node]
2025-10-13 00:11:25.585804 | controller | ok
2025-10-13 00:11:25.591742 | 
2025-10-13 00:11:25.591815 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 00:11:26.026380 | controller -> localhost | ok: "/var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/logs"
2025-10-13 00:11:26.306850 | controller -> localhost | changed: "/var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/artifacts"
2025-10-13 00:11:26.584898 | controller -> localhost | changed: "/var/lib/zuul/builds/45e942a97a744b8d86346662424453aa/work/docs"
2025-10-13 00:11:26.600143 | 
2025-10-13 00:11:26.600296 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 00:11:27.928867 | controller | changed:
2025-10-13 00:11:27.929266 | controller | .d..t...... ./
2025-10-13 00:11:27.929333 | controller | cd+++++++++ controller/
2025-10-13 00:11:27.929403 | controller | changed: All items complete
2025-10-13 00:11:27.929456 | 
2025-10-13 00:11:29.928673 | controller | changed: .d..t...... ./
2025-10-13 00:11:31.011424 | controller | changed: .d..t...... ./
2025-10-13 00:11:31.030710 | 
2025-10-13 00:11:31.030824 | TASK [include_role : fetch-output-openshift]
2025-10-13 00:11:31.054671 | controller | skipping: Conditional result was False
2025-10-13 00:11:31.061550 | 
2025-10-13 00:11:31.061637 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 00:11:31.119026 | controller | skipping: Conditional result was False
2025-10-13 00:11:31.140681 | controller | skipping: Conditional result was False
2025-10-13 00:11:31.189776 | 
2025-10-13 00:11:31.189938 | PLAY [localhost]
2025-10-13 00:11:31.208327 | 
2025-10-13 00:11:31.208456 | TASK [Run Zuul manifest role]
2025-10-13 00:11:31.228403 | localhost | ok
2025-10-13 00:11:31.241486 | 
2025-10-13 00:11:31.241592 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 00:11:31.584973 | localhost | changed
2025-10-13 00:11:31.590000 | 
2025-10-13 00:11:31.590065 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 00:11:31.620602 | localhost | ok
2025-10-13 00:11:31.628642 | 
2025-10-13 00:11:31.628740 | TASK [Set zuul-log-path fact]
2025-10-13 00:11:31.646047 | localhost | ok
2025-10-13 00:11:31.660875 | 
2025-10-13 00:11:31.660953 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 00:11:31.688830 | localhost | ok
2025-10-13 00:11:31.696859 | 
2025-10-13 00:11:31.696915 | LOOP [Run upload-logs-swift role]
2025-10-13 00:11:31.751600 | localhost | Output suppressed because no_log was given
2025-10-13 00:11:31.775667 | 
2025-10-13 00:11:31.775751 | TASK [Set zuul-log-path fact]
2025-10-13 00:11:31.799299 | localhost | skipping: Conditional result was False
2025-10-13 00:11:31.804450 | 
2025-10-13 00:11:31.804516 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-13 00:11:32.204775 | localhost -> localhost | ok: Runtime: 0:00:00.010030
2025-10-13 00:11:32.209430 | 
2025-10-13 00:11:32.209498 | TASK [upload-logs-swift : Upload logs to swift]