2025-09-26 00:06:29.505349 | Job console starting...
2025-09-26 00:06:29.513409 | Updating repositories
2025-09-26 00:06:29.707686 | Preparing job workspace
2025-09-26 00:06:35.786444 | Running Ansible setup...
2025-09-26 00:06:42.079887 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-26 00:06:42.885388 | 
2025-09-26 00:06:42.885522 | PLAY [localhost]
2025-09-26 00:06:42.894960 | 
2025-09-26 00:06:42.895054 | TASK [Gathering Facts]
2025-09-26 00:06:43.905377 | localhost | ok
2025-09-26 00:06:43.937205 | 
2025-09-26 00:06:43.937511 | TASK [Setup log path fact]
2025-09-26 00:06:43.956592 | localhost | ok
2025-09-26 00:06:43.970465 | 
2025-09-26 00:06:43.970585 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-26 00:06:43.999517 | localhost | ok
2025-09-26 00:06:44.007884 | 
2025-09-26 00:06:44.007991 | TASK [emit-job-header : Print job information]
2025-09-26 00:06:44.057439 | # Job Information
2025-09-26 00:06:44.057618 | Ansible Version: 2.15.12
2025-09-26 00:06:44.057660 | Job: ansible-test-sanity-docker-milestone
2025-09-26 00:06:44.057690 | Pipeline: periodic
2025-09-26 00:06:44.057717 | Executor: ze01.softwarefactory-project.io
2025-09-26 00:06:44.057743 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-26 00:06:44.057772 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/7ac/ansible/7acdfe9978c147949ee8dba0ea06ad89/
2025-09-26 00:06:44.057798 | Event ID: 5696abddc46a4c7696f30c6b91218f52
2025-09-26 00:06:44.069789 | 
2025-09-26 00:06:44.069920 | LOOP [emit-job-header : Print node information]
2025-09-26 00:06:44.203360 | localhost | ok:
2025-09-26 00:06:44.203632 | localhost | # Node Information
2025-09-26 00:06:44.203676 | localhost | Inventory Hostname: controller
2025-09-26 00:06:44.203707 | localhost | Hostname: ip-172-16-198-151
2025-09-26 00:06:44.203736 | localhost | Username: zuul-worker
2025-09-26 00:06:44.203767 | localhost | Distro: Fedora 37
2025-09-26 00:06:44.203795 | localhost | Provider: ansible-us-east-2
2025-09-26 00:06:44.203820 | localhost | Region: us-east-2
2025-09-26 00:06:44.203847 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-26 00:06:44.203872 | localhost | Product Name: t3.small
2025-09-26 00:06:44.203899 | localhost | Interface IP: 3.143.236.135
2025-09-26 00:06:44.220191 | 
2025-09-26 00:06:44.220306 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-26 00:06:44.622628 | localhost -> localhost | changed
2025-09-26 00:06:44.628946 | 
2025-09-26 00:06:44.629088 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-26 00:06:45.959285 | localhost -> localhost | changed
2025-09-26 00:06:46.016154 | 
2025-09-26 00:06:46.016274 | PLAY [all:!appliance*]
2025-09-26 00:06:46.056059 | 
2025-09-26 00:06:46.056200 | TASK [include_role : start-zuul-console]
2025-09-26 00:06:46.093662 | controller | ok
2025-09-26 00:06:46.125381 | 
2025-09-26 00:06:46.125520 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-26 00:06:46.942081 | controller | ok
2025-09-26 00:06:46.972060 | 
2025-09-26 00:06:46.972216 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-26 00:06:48.377269 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-26 00:06:48.391830 | 
2025-09-26 00:06:48.391937 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-26 00:06:48.554250 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.562300 | 
2025-09-26 00:06:48.562551 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-26 00:06:48.587737 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.594210 | 
2025-09-26 00:06:48.594290 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-26 00:06:48.623766 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.630228 | 
2025-09-26 00:06:48.630307 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-26 00:06:48.645129 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.652815 | 
2025-09-26 00:06:48.652906 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-26 00:06:48.677691 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.683250 | 
2025-09-26 00:06:48.683315 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-26 00:06:48.707481 | controller | skipping: Conditional result was False
2025-09-26 00:06:48.720498 | 
2025-09-26 00:06:48.720569 | TASK [Disable Fedora Modular]
2025-09-26 00:06:49.507182 | controller | changed
2025-09-26 00:06:49.513475 | 
2025-09-26 00:06:49.513608 | TASK [Enable EPEL]
2025-09-26 00:06:49.538060 | controller | skipping: Conditional result was False
2025-09-26 00:06:49.550563 | 
2025-09-26 00:06:49.550704 | TASK [Register the RHEL node]
2025-09-26 00:06:49.715931 | 
2025-09-26 00:06:49.716110 | TASK [Show the subscription-manager status]
2025-09-26 00:06:49.952624 | controller | skipping: Conditional result was False
2025-09-26 00:06:49.959079 | 
2025-09-26 00:06:49.959149 | TASK [Enable EPEL on RHEL]
2025-09-26 00:06:50.119865 | controller | skipping: Conditional result was False
2025-09-26 00:06:50.128225 | 
2025-09-26 00:06:50.128375 | TASK [Install git and tox]
2025-09-26 00:08:18.026303 | controller | changed
2025-09-26 00:08:18.032461 | 
2025-09-26 00:08:18.032526 | TASK [include_role : prepare-workspace]
2025-09-26 00:08:18.068164 | controller | ok
2025-09-26 00:08:18.099821 | 
2025-09-26 00:08:18.099945 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-26 00:08:18.712519 | controller | ok
2025-09-26 00:08:18.723770 | 
2025-09-26 00:08:18.723872 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-26 00:08:31.963219 | controller | Output suppressed because no_log was given
2025-09-26 00:08:31.976902 | 
2025-09-26 00:08:31.976999 | TASK [include_role : prepare-workspace-openshift]
2025-09-26 00:08:31.993192 | controller | skipping: Conditional result was False
2025-09-26 00:08:32.016593 | 
2025-09-26 00:08:32.016664 | PLAY [all:!appliance]
2025-09-26 00:08:32.031898 | 
2025-09-26 00:08:32.031961 | TASK [Run add-build-sshkey role (RSA)]
2025-09-26 00:08:32.071325 | controller | ok
2025-09-26 00:08:32.117984 | 
2025-09-26 00:08:32.118127 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-26 00:08:32.389594 | controller -> localhost | ok
2025-09-26 00:08:32.396089 | 
2025-09-26 00:08:32.396165 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-26 00:08:32.417445 | controller | ok
2025-09-26 00:08:32.436579 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-26 00:08:32.443938 | 
2025-09-26 00:08:32.444008 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-26 00:08:32.917198 | controller -> localhost | Generating public/private rsa key pair.
2025-09-26 00:08:32.917399 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_rsa.
2025-09-26 00:08:32.917444 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_rsa.pub.
2025-09-26 00:08:32.917467 | controller -> localhost | The key fingerprint is:
2025-09-26 00:08:32.917489 | controller -> localhost | SHA256:03azWol4/XWa/aX3Ktet5FAinTuS/zRJ20Me71n4D1g zuul-build-sshkey
2025-09-26 00:08:32.917508 | controller -> localhost | The key's randomart image is:
2025-09-26 00:08:32.917528 | controller -> localhost | +---[RSA 2048]----+
2025-09-26 00:08:32.917546 | controller -> localhost | |                 |
2025-09-26 00:08:32.917565 | controller -> localhost | |                 |
2025-09-26 00:08:32.917585 | controller -> localhost | |                 |
2025-09-26 00:08:32.917603 | controller -> localhost | |         . . .   |
2025-09-26 00:08:32.917621 | controller -> localhost | |        S + * Eo |
2025-09-26 00:08:32.917649 | controller -> localhost | |         + * @o=o|
2025-09-26 00:08:32.917672 | controller -> localhost | |        . = X O+O|
2025-09-26 00:08:32.917842 | controller -> localhost | |         . =.B.@X|
2025-09-26 00:08:32.917872 | controller -> localhost | |          . .+X=@|
2025-09-26 00:08:32.917896 | controller -> localhost | +----[SHA256]-----+
2025-09-26 00:08:32.918293 | controller -> localhost | ok: Runtime: 0:00:00.097449
2025-09-26 00:08:32.924909 | 
2025-09-26 00:08:32.924985 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-26 00:08:32.964199 | controller | ok
2025-09-26 00:08:32.975720 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-26 00:08:32.986093 | 
2025-09-26 00:08:32.986188 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-26 00:08:33.011195 | controller | skipping: Conditional result was False
2025-09-26 00:08:33.017364 | 
2025-09-26 00:08:33.017438 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-26 00:08:33.628006 | controller | changed
2025-09-26 00:08:33.639244 | 
2025-09-26 00:08:33.639362 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-26 00:08:34.040663 | controller | ok
2025-09-26 00:08:34.061465 | 
2025-09-26 00:08:34.061594 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-26 00:08:35.480388 | controller | changed
2025-09-26 00:08:35.486073 | 
2025-09-26 00:08:35.486173 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-26 00:08:36.774140 | controller | changed
2025-09-26 00:08:36.782973 | 
2025-09-26 00:08:36.783136 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-26 00:08:36.809269 | controller | skipping: Conditional result was False
2025-09-26 00:08:36.819443 | 
2025-09-26 00:08:36.819567 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-26 00:08:37.182856 | controller -> localhost | changed
2025-09-26 00:08:37.194771 | 
2025-09-26 00:08:37.194861 | TASK [add-build-sshkey : Add back temp key]
2025-09-26 00:08:37.474966 | controller -> localhost | Identity added: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_rsa (zuul-build-sshkey)
2025-09-26 00:08:37.475345 | controller -> localhost | ok: Runtime: 0:00:00.014226
2025-09-26 00:08:37.490391 | 
2025-09-26 00:08:37.490546 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-26 00:08:38.014912 | controller | ok
2025-09-26 00:08:38.023373 | 
2025-09-26 00:08:38.023466 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-26 00:08:38.048876 | controller | skipping: Conditional result was False
2025-09-26 00:08:38.067578 | 
2025-09-26 00:08:38.067737 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-26 00:08:38.095576 | controller | ok
2025-09-26 00:08:38.125432 | 
2025-09-26 00:08:38.125560 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-26 00:08:38.364695 | controller -> localhost | ok
2025-09-26 00:08:38.374485 | 
2025-09-26 00:08:38.374593 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-26 00:08:38.400343 | controller | ok
2025-09-26 00:08:38.418645 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-26 00:08:38.427797 | 
2025-09-26 00:08:38.427889 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-26 00:08:38.717448 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-26 00:08:38.717699 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_ecdsa.
2025-09-26 00:08:38.717729 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_ecdsa.pub.
2025-09-26 00:08:38.717759 | controller -> localhost | The key fingerprint is:
2025-09-26 00:08:38.717780 | controller -> localhost | SHA256:cMm4YS/GWOUO4L9dMnFUHvFoL6gEqmz6ezQi69DnWTg zuul-build-sshkey
2025-09-26 00:08:38.717802 | controller -> localhost | The key's randomart image is:
2025-09-26 00:08:38.717822 | controller -> localhost | +---[ECDSA 521]---+
2025-09-26 00:08:38.717841 | controller -> localhost | |    .   . ..+.   |
2025-09-26 00:08:38.717861 | controller -> localhost | |   . . = o . +   |
2025-09-26 00:08:38.717879 | controller -> localhost | |    . O * . + .  |
2025-09-26 00:08:38.717898 | controller -> localhost | |     B X o o .   |
2025-09-26 00:08:38.717916 | controller -> localhost | |    o * S o . .  |
2025-09-26 00:08:38.717934 | controller -> localhost | |.o..oo = =   .   |
2025-09-26 00:08:38.717952 | controller -> localhost | |.o=oE.o o        |
2025-09-26 00:08:38.717970 | controller -> localhost | |oo o.+           |
2025-09-26 00:08:38.717988 | controller -> localhost | |ooooo            |
2025-09-26 00:08:38.718006 | controller -> localhost | +----[SHA256]-----+
2025-09-26 00:08:38.718091 | controller -> localhost | ok: Runtime: 0:00:00.010617
2025-09-26 00:08:38.725760 | 
2025-09-26 00:08:38.725830 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-26 00:08:38.757800 | controller | ok
2025-09-26 00:08:38.765175 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-26 00:08:38.774728 | 
2025-09-26 00:08:38.774796 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-26 00:08:38.809664 | controller | skipping: Conditional result was False
2025-09-26 00:08:38.816165 | 
2025-09-26 00:08:38.816231 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-26 00:08:39.318697 | controller | changed
2025-09-26 00:08:39.330630 | 
2025-09-26 00:08:39.330744 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-26 00:08:39.707205 | controller | ok
2025-09-26 00:08:39.721612 | 
2025-09-26 00:08:39.721758 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-26 00:08:41.324124 | controller | changed
2025-09-26 00:08:41.337166 | 
2025-09-26 00:08:41.337325 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-26 00:08:42.970127 | controller | changed
2025-09-26 00:08:42.979594 | 
2025-09-26 00:08:42.979747 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-26 00:08:43.006794 | controller | skipping: Conditional result was False
2025-09-26 00:08:43.016753 | 
2025-09-26 00:08:43.016870 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-26 00:08:43.309473 | controller -> localhost | changed
2025-09-26 00:08:43.322812 | 
2025-09-26 00:08:43.322913 | TASK [add-build-sshkey : Add back temp key]
2025-09-26 00:08:43.675863 | controller -> localhost | Identity added: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/7acdfe9978c147949ee8dba0ea06ad89_id_ecdsa (zuul-build-sshkey)
2025-09-26 00:08:43.676172 | controller -> localhost | ok: Runtime: 0:00:00.007809
2025-09-26 00:08:43.687549 | 
2025-09-26 00:08:43.687665 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-26 00:08:44.057928 | controller | ok
2025-09-26 00:08:44.065622 | 
2025-09-26 00:08:44.065731 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-26 00:08:44.111169 | controller | skipping: Conditional result was False
2025-09-26 00:08:44.126275 | 
2025-09-26 00:08:44.126385 | TASK [include_role : remove-zuul-sshkey]
2025-09-26 00:08:44.150896 | controller | skipping: Conditional result was False
2025-09-26 00:08:44.159811 | 
2025-09-26 00:08:44.159911 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-26 00:08:44.526939 | controller | ok: "logs"
2025-09-26 00:08:44.527458 | controller | ok: All items complete
2025-09-26 00:08:44.527541 | 
2025-09-26 00:08:44.831606 | controller | ok: "artifacts"
2025-09-26 00:08:45.143767 | controller | ok: "docs"
2025-09-26 00:08:45.157859 | 
2025-09-26 00:08:45.158107 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-26 00:08:45.537425 | controller | changed: "logs"
2025-09-26 00:08:45.850643 | controller | changed: "artifacts"
2025-09-26 00:08:46.163789 | controller | changed: "docs"
2025-09-26 00:08:46.222689 | 
2025-09-26 00:08:46.222798 | PLAY RECAP
2025-09-26 00:08:46.222855 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-26 00:08:46.222890 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-26 00:08:46.222915 | 
2025-09-26 00:08:46.348920 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-26 00:08:46.349846 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-26 00:08:47.001184 | 
2025-09-26 00:08:47.001313 | PLAY [all]
2025-09-26 00:08:47.033134 | 
2025-09-26 00:08:47.033380 | TASK [Install binary dependencies]
2025-09-26 00:08:47.083979 | controller | ok
2025-09-26 00:08:47.103560 | 
2025-09-26 00:08:47.103684 | TASK [bindep : Include find tasks]
2025-09-26 00:08:47.144717 | controller | ok
2025-09-26 00:08:47.153396 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-26 00:08:47.160273 | 
2025-09-26 00:08:47.160368 | TASK [bindep : Look for bindep.txt]
2025-09-26 00:08:47.687443 | controller | ok
2025-09-26 00:08:47.704073 | 
2025-09-26 00:08:47.704243 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:08:47.732347 | controller | skipping: Conditional result was False
2025-09-26 00:08:47.746547 | 
2025-09-26 00:08:47.746688 | TASK [bindep : Look for other-requirements.txt]
2025-09-26 00:08:48.098944 | controller | ok
2025-09-26 00:08:48.113147 | 
2025-09-26 00:08:48.113274 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:08:48.189464 | controller | skipping: Conditional result was False
2025-09-26 00:08:48.199902 | 
2025-09-26 00:08:48.200042 | TASK [bindep : Look for bindep fallback file]
2025-09-26 00:08:48.225832 | controller | skipping: Conditional result was False
2025-09-26 00:08:48.238787 | 
2025-09-26 00:08:48.238925 | TASK [bindep : Define bindep_file fact]
2025-09-26 00:08:48.265752 | controller | skipping: Conditional result was False
2025-09-26 00:08:48.277340 | 
2025-09-26 00:08:48.277454 | TASK [bindep : Include bindep tasks]
2025-09-26 00:08:48.303364 | controller | skipping: Conditional result was False
2025-09-26 00:08:48.313267 | 
2025-09-26 00:08:48.313398 | TASK [bindep : Include install tasks]
2025-09-26 00:08:48.374288 | controller | skipping: Conditional result was False
2025-09-26 00:08:48.380299 | 
2025-09-26 00:08:48.380364 | LOOP [bindep : Include package tasks]
2025-09-26 00:08:48.511720 | 
2025-09-26 00:08:48.511919 | TASK [Run test-setup role]
2025-09-26 00:08:48.534897 | controller | ok
2025-09-26 00:08:48.564979 | 
2025-09-26 00:08:48.565234 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-26 00:08:48.907125 | controller | ok
2025-09-26 00:08:48.913890 | 
2025-09-26 00:08:48.914131 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-26 00:08:49.053527 | controller | skipping: Conditional result was False
2025-09-26 00:08:49.102742 | 
2025-09-26 00:08:49.103077 | PLAY RECAP
2025-09-26 00:08:49.103210 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-26 00:08:49.103259 | 
2025-09-26 00:08:49.226385 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-26 00:08:49.227245 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-26 00:08:49.935787 | 
2025-09-26 00:08:49.935929 | PLAY [controller]
2025-09-26 00:08:49.958450 | 
2025-09-26 00:08:49.958571 | TASK [Create the /root directory]
2025-09-26 00:08:50.748341 | controller | ok
2025-09-26 00:08:50.766852 | 
2025-09-26 00:08:50.766956 | TASK [Install glibc-langpack-en]
2025-09-26 00:08:58.862411 | controller | ok: Nothing to do
2025-09-26 00:08:58.871136 | 
2025-09-26 00:08:58.871252 | TASK [Ensure controller directory exists]
2025-09-26 00:08:59.285315 | controller | changed
2025-09-26 00:08:59.293707 | 
2025-09-26 00:08:59.293833 | TASK [Install container runtime]
2025-09-26 00:08:59.348718 | controller | ok
2025-09-26 00:08:59.397266 | 
2025-09-26 00:08:59.397532 | LOOP [ensure-podman : Find distribution installation]
2025-09-26 00:08:59.433929 | controller | ok: "/var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-26 00:08:59.451776 | controller | included: /var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-26 00:08:59.457983 | 
2025-09-26 00:08:59.458082 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-26 00:10:16.207281 | controller | changed
2025-09-26 00:10:16.218722 | 
2025-09-26 00:10:16.218906 | TASK [ensure-podman : Fetch podman version]
2025-09-26 00:10:16.923297 | controller | Client:       Podman Engine
2025-09-26 00:10:16.950400 | controller | Version:      4.6.2
2025-09-26 00:10:16.950441 | controller | API Version:  4.6.2
2025-09-26 00:10:16.950448 | controller | Go Version:   go1.19.12
2025-09-26 00:10:16.950464 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-26 00:10:16.950471 | controller | OS/Arch:      linux/amd64
2025-09-26 00:10:17.370667 | controller | ok: Runtime: 0:00:00.215416
2025-09-26 00:10:17.377424 | 
2025-09-26 00:10:17.377599 | TASK [ensure-podman : Print podman version installed]
2025-09-26 00:10:17.398104 | Podman version: Client:       Podman Engine
2025-09-26 00:10:17.398254 | Version:      4.6.2
2025-09-26 00:10:17.398284 | API Version:  4.6.2
2025-09-26 00:10:17.398306 | Go Version:   go1.19.12
2025-09-26 00:10:17.398326 | Built:        Mon Aug 28 19:38:31 2023
2025-09-26 00:10:17.398345 | OS/Arch:      linux/amd64
2025-09-26 00:10:17.404098 | 
2025-09-26 00:10:17.404168 | TASK [ensure-podman : Validate podman engine]
2025-09-26 00:10:17.540085 | controller | skipping: Conditional result was False
2025-09-26 00:10:17.546715 | 
2025-09-26 00:10:17.546812 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-26 00:10:17.562407 | controller | skipping: Conditional result was False
2025-09-26 00:10:17.578108 | 
2025-09-26 00:10:17.578313 | TASK [Ensure python3.8 is present]
2025-09-26 00:10:17.605847 | controller | skipping: Conditional result was False
2025-09-26 00:10:17.616541 | 
2025-09-26 00:10:17.616758 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-26 00:10:17.654750 | controller | ok
2025-09-26 00:10:17.685475 | 
2025-09-26 00:10:17.685653 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-26 00:10:21.487095 | controller | ok: Nothing to do
2025-09-26 00:10:21.501592 | 
2025-09-26 00:10:21.501877 | TASK [our-ensure-python : Also install python3-devel]
2025-09-26 00:10:34.697213 | controller | changed
2025-09-26 00:10:34.722974 | 
2025-09-26 00:10:34.723196 | TASK [Run ensure-virtualenv role]
2025-09-26 00:10:34.747453 | controller | ok
2025-09-26 00:10:34.775765 | 
2025-09-26 00:10:34.775905 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-26 00:10:35.154031 | controller | /usr/bin/virtualenv
2025-09-26 00:10:35.410354 | controller | ok: Runtime: 0:00:00.004748
2025-09-26 00:10:35.419774 | 
2025-09-26 00:10:35.419991 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-26 00:10:35.438105 | controller | skipping: Conditional result was False
2025-09-26 00:10:35.438429 | controller | ok: All items complete
2025-09-26 00:10:35.438468 | 
2025-09-26 00:10:35.460417 | 
2025-09-26 00:10:35.460556 | TASK [Find the full path of the Python interpreter]
2025-09-26 00:10:35.799825 | controller | /usr/bin/python3
2025-09-26 00:10:36.106423 | controller | ok
2025-09-26 00:10:36.114226 | 
2025-09-26 00:10:36.114934 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-26 00:10:37.524299 | controller | created virtual environment CPython3.11.0.final.0-64 in 736ms
2025-09-26 00:10:37.564500 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-26 00:10:37.564560 | 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:10:37.564578 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-26 00:10:37.564602 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-26 00:10:37.764170 | controller | changed
2025-09-26 00:10:37.778497 | 
2025-09-26 00:10:37.778679 | TASK [Set selinux package]
2025-09-26 00:10:37.820240 | controller | ok
2025-09-26 00:10:37.832369 | 
2025-09-26 00:10:37.832552 | TASK [Set selinux package (Fedora)]
2025-09-26 00:10:37.880092 | controller | ok
2025-09-26 00:10:37.887931 | 
2025-09-26 00:10:37.888058 | TASK [Install selinux into virtualenv]
2025-09-26 00:10:40.525485 | controller | Collecting selinux-please-lie-to-me
2025-09-26 00:10:40.614440 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-26 00:10:41.160830 | controller | Collecting setuptools<50.0.0
2025-09-26 00:10:41.174566 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-26 00:10:41.297923 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-09-26 00:10:41.450407 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-26 00:10:41.450829 | controller |   Attempting uninstall: setuptools
2025-09-26 00:10:41.455784 | controller |     Found existing installation: setuptools 62.6.0
2025-09-26 00:10:41.567122 | controller |     Uninstalling setuptools-62.6.0:
2025-09-26 00:10:41.582058 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-26 00:10:42.337926 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-26 00:10:42.546733 | controller |
2025-09-26 00:10:42.755723 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-26 00:10:42.755773 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-26 00:10:43.119170 | controller | ok: Runtime: 0:00:04.392541
2025-09-26 00:10:43.125999 | 
2025-09-26 00:10:43.126157 | TASK [Install pytest-forked into virtualenv]
2025-09-26 00:10:44.329924 | controller | Collecting pytest-forked
2025-09-26 00:10:44.416282 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-26 00:10:44.474457 | controller | Collecting py
2025-09-26 00:10:44.487332 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-26 00:10:44.527554 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-09-26 00:10:44.703976 | controller | Collecting pytest>=3.10
2025-09-26 00:10:44.715981 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-26 00:10:44.776771 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-09-26 00:10:44.833215 | controller | Collecting iniconfig>=1
2025-09-26 00:10:44.845288 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-26 00:10:44.912499 | controller | Collecting packaging>=20
2025-09-26 00:10:44.925941 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-26 00:10:44.938399 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00
2025-09-26 00:10:44.986670 | controller | Collecting pluggy<2,>=1.5
2025-09-26 00:10:45.001077 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-26 00:10:45.074742 | controller | Collecting pygments>=2.7.2
2025-09-26 00:10:45.087234 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-26 00:10:45.204517 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-09-26 00:10:45.337442 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-26 00:10:47.578410 | 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:10:47.594564 | controller |
2025-09-26 00:10:47.774054 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-26 00:10:47.774108 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-26 00:10:48.274717 | controller | ok: Runtime: 0:00:04.169046
2025-09-26 00:10:48.283144 | 
2025-09-26 00:10:48.283268 | TASK [Update pip]
2025-09-26 00:10:49.357881 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-26 00:10:49.621122 | controller | Collecting pip
2025-09-26 00:10:49.711472 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-26 00:10:49.880200 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.7 MB/s eta 0:00:00
2025-09-26 00:10:50.027932 | controller | Installing collected packages: pip
2025-09-26 00:10:50.028388 | controller |   Attempting uninstall: pip
2025-09-26 00:10:50.032858 | controller |     Found existing installation: pip 22.2.2
2025-09-26 00:10:50.294052 | controller |     Uninstalling pip-22.2.2:
2025-09-26 00:10:50.323842 | controller |       Successfully uninstalled pip-22.2.2
2025-09-26 00:10:52.043765 | controller | Successfully installed pip-25.2
2025-09-26 00:10:52.561409 | controller | ok: Runtime: 0:00:03.470273
2025-09-26 00:10:52.566479 | 
2025-09-26 00:10:52.566537 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-26 00:10:53.071800 | controller | changed
2025-09-26 00:10:53.080525 | 
2025-09-26 00:10:53.080651 | TASK [Install ansible into virtualenv]
2025-09-26 00:10:54.147884 | controller | Processing ./src/github.com/ansible/ansible
2025-09-26 00:10:54.154362 | controller |   Installing build dependencies: started
2025-09-26 00:10:56.007527 | controller |   Installing build dependencies: finished with status 'done'
2025-09-26 00:10:57.527037 | controller |   Getting requirements to build wheel: started
2025-09-26 00:10:57.527100 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-26 00:10:58.448217 | controller |   Preparing metadata (pyproject.toml): started
2025-09-26 00:10:58.448273 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-26 00:10:58.452782 | 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:10:58.452833 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-26 00:10:58.741230 | controller | ERROR
2025-09-26 00:10:58.741440 | controller | {
2025-09-26 00:10:58.741469 | controller |   "delta": "0:00:05.077871",
2025-09-26 00:10:58.741502 | controller |   "end": "2025-09-26 00:10:58.600881",
2025-09-26 00:10:58.741546 | controller |   "msg": "non-zero return code",
2025-09-26 00:10:58.741586 | controller |   "rc": 1,
2025-09-26 00:10:58.741604 | controller |   "start": "2025-09-26 00:10:53.523010"
2025-09-26 00:10:58.741620 | controller | }
failure
2025-09-26 00:10:58.743476 | 
2025-09-26 00:10:58.743537 | PLAY RECAP
2025-09-26 00:10:58.743587 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-26 00:10:58.743609 | 
2025-09-26 00:10:58.906056 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-26 00:10:58.907429 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-26 00:10:59.532798 | 
2025-09-26 00:10:59.533129 | PLAY [all]
2025-09-26 00:10:59.557997 | 
2025-09-26 00:10:59.558158 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-26 00:11:00.402783 | controller | changed: non-zero return code
2025-09-26 00:11:00.409631 | 
2025-09-26 00:11:00.409775 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-26 00:11:00.435529 | controller | skipping: Conditional result was False
2025-09-26 00:11:00.443452 | 
2025-09-26 00:11:00.443611 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-26 00:11:00.470278 | 
2025-09-26 00:11:00.470507 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-26 00:11:00.503539 | 
2025-09-26 00:11:00.503722 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-26 00:11:00.519681 | controller | skipping: Conditional result was False
2025-09-26 00:11:00.527270 | 
2025-09-26 00:11:00.527388 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-26 00:11:00.560108 | 
2025-09-26 00:11:00.560323 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-26 00:11:00.574992 | controller | skipping: Conditional result was False
2025-09-26 00:11:00.582557 | 
2025-09-26 00:11:00.582683 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-26 00:11:00.597524 | controller | skipping: Conditional result was False
2025-09-26 00:11:00.605606 | 
2025-09-26 00:11:00.605725 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-26 00:11:00.620109 | controller | skipping: Conditional result was False
2025-09-26 00:11:00.654846 | 
2025-09-26 00:11:00.654945 | PLAY RECAP
2025-09-26 00:11:00.654985 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-26 00:11:00.655006 | 
2025-09-26 00:11:00.788670 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-26 00:11:00.789554 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-26 00:11:01.409474 | 
2025-09-26 00:11:01.409651 | PLAY [all:!appliance*]
2025-09-26 00:11:01.434300 | 
2025-09-26 00:11:01.434470 | TASK [unregister the node]
2025-09-26 00:11:01.573765 | controller | skipping: Conditional result was False
2025-09-26 00:11:01.580125 | 
2025-09-26 00:11:01.580251 | TASK [include_role : fetch-output]
2025-09-26 00:11:01.610355 | controller | ok
2025-09-26 00:11:01.634106 | 
2025-09-26 00:11:01.634255 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-26 00:11:01.679274 | controller | skipping: Conditional result was False
2025-09-26 00:11:01.686876 | 
2025-09-26 00:11:01.686999 | TASK [fetch-output : Set log path for single node]
2025-09-26 00:11:01.727987 | controller | ok
2025-09-26 00:11:01.733744 | 
2025-09-26 00:11:01.733862 | LOOP [fetch-output : Ensure local output dirs]
2025-09-26 00:11:02.235622 | controller -> localhost | ok: "/var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/logs"
2025-09-26 00:11:02.482560 | controller -> localhost | changed: "/var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/artifacts"
2025-09-26 00:11:02.741227 | controller -> localhost | changed: "/var/lib/zuul/builds/7acdfe9978c147949ee8dba0ea06ad89/work/docs"
2025-09-26 00:11:02.766952 | 
2025-09-26 00:11:02.767099 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-26 00:11:03.995039 | controller | changed:
2025-09-26 00:11:03.995246 | controller | .d..t...... ./
2025-09-26 00:11:03.995277 | controller | cd+++++++++ controller/
2025-09-26 00:11:03.995315 | controller | changed: All items complete
2025-09-26 00:11:03.995359 | 
2025-09-26 00:11:05.060324 | controller | changed: .d..t...... ./
2025-09-26 00:11:06.121542 | controller | changed: .d..t...... ./
2025-09-26 00:11:06.143295 | 
2025-09-26 00:11:06.143479 | TASK [include_role : fetch-output-openshift]
2025-09-26 00:11:06.170816 | controller | skipping: Conditional result was False
2025-09-26 00:11:06.184802 | 
2025-09-26 00:11:06.184999 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-26 00:11:06.229755 | controller | skipping: Conditional result was False
2025-09-26 00:11:06.244556 | controller | skipping: Conditional result was False
2025-09-26 00:11:06.291170 | 
2025-09-26 00:11:06.291361 | PLAY [localhost]
2025-09-26 00:11:06.309358 | 
2025-09-26 00:11:06.309476 | TASK [Run Zuul manifest role]
2025-09-26 00:11:06.328760 | localhost | ok
2025-09-26 00:11:06.343493 | 
2025-09-26 00:11:06.343626 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-26 00:11:06.799155 | localhost | changed
2025-09-26 00:11:06.810803 | 
2025-09-26 00:11:06.810986 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-26 00:11:06.849890 | localhost | ok
2025-09-26 00:11:06.863137 | 
2025-09-26 00:11:06.863286 | TASK [Set zuul-log-path fact]
2025-09-26 00:11:06.886420 | localhost | ok
2025-09-26 00:11:06.909207 | 
2025-09-26 00:11:06.909358 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-26 00:11:06.939320 | localhost | ok
2025-09-26 00:11:06.949550 | 
2025-09-26 00:11:06.949700 | LOOP [Run upload-logs-swift role]
2025-09-26 00:11:06.985516 | localhost | Output suppressed because no_log was given
2025-09-26 00:11:07.025719 | 
2025-09-26 00:11:07.025875 | TASK [Set zuul-log-path fact]
2025-09-26 00:11:07.063553 | localhost | skipping: Conditional result was False
2025-09-26 00:11:07.069062 | 
2025-09-26 00:11:07.070455 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-26 00:11:07.504845 | localhost -> localhost | ok: Runtime: 0:00:00.006335
2025-09-26 00:11:07.512867 | 
2025-09-26 00:11:07.512989 | TASK [upload-logs-swift : Upload logs to swift]