2025-11-09 00:06:40.315152 | Job console starting...
2025-11-09 00:06:40.329278 | Updating repositories
2025-11-09 00:06:40.460863 | Preparing job workspace
2025-11-09 00:06:44.638524 | Running Ansible setup...
2025-11-09 00:06:49.143826 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-09 00:06:49.726145 | 
2025-11-09 00:06:49.726267 | PLAY [localhost]
2025-11-09 00:06:49.734349 | 
2025-11-09 00:06:49.734417 | TASK [Gathering Facts]
2025-11-09 00:06:50.788793 | localhost | ok
2025-11-09 00:06:50.808817 | 
2025-11-09 00:06:50.808933 | TASK [Setup log path fact]
2025-11-09 00:06:50.828967 | localhost | ok
2025-11-09 00:06:50.845940 | 
2025-11-09 00:06:50.846027 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-09 00:06:50.886640 | localhost | ok
2025-11-09 00:06:50.897392 | 
2025-11-09 00:06:50.897488 | TASK [emit-job-header : Print job information]
2025-11-09 00:06:50.938123 | # Job Information
2025-11-09 00:06:50.938277 | Ansible Version: 2.15.12
2025-11-09 00:06:50.938318 | Job: ansible-test-sanity-docker-devel
2025-11-09 00:06:50.938347 | Pipeline: periodic
2025-11-09 00:06:50.938372 | Executor: ze02.softwarefactory-project.io
2025-11-09 00:06:50.938397 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-09 00:06:50.938429 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fda/ansible/fdaa60f417b54405be4beeb8f70427df/
2025-11-09 00:06:50.938456 | Event ID: 280be395c61a4a10afa9abd9d444e89a
2025-11-09 00:06:50.943751 | 
2025-11-09 00:06:50.943837 | LOOP [emit-job-header : Print node information]
2025-11-09 00:06:51.056659 | localhost | ok:
2025-11-09 00:06:51.057057 | localhost | # Node Information
2025-11-09 00:06:51.057117 | localhost | Inventory Hostname: controller
2025-11-09 00:06:51.057161 | localhost | Hostname: np0005515813
2025-11-09 00:06:51.057201 | localhost | Username: zuul
2025-11-09 00:06:51.057254 | localhost | Distro: Fedora 37
2025-11-09 00:06:51.057296 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-09 00:06:51.057334 | localhost | Region: ca-ymq-1
2025-11-09 00:06:51.057371 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-09 00:06:51.057408 | localhost | Product Name: OpenStack Nova
2025-11-09 00:06:51.057444 | localhost | Interface IP: 162.253.55.145
2025-11-09 00:06:51.078406 | 
2025-11-09 00:06:51.078569 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-09 00:06:51.455299 | localhost -> localhost | changed
2025-11-09 00:06:51.469039 | 
2025-11-09 00:06:51.469231 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-09 00:06:52.440399 | localhost -> localhost | changed
2025-11-09 00:06:52.463003 | 
2025-11-09 00:06:52.463090 | PLAY [all:!appliance*]
2025-11-09 00:06:52.481321 | 
2025-11-09 00:06:52.481448 | TASK [include_role : start-zuul-console]
2025-11-09 00:06:52.500872 | controller | ok
2025-11-09 00:06:52.515876 | 
2025-11-09 00:06:52.515994 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-09 00:06:52.911738 | controller | ok
2025-11-09 00:06:52.922272 | 
2025-11-09 00:06:52.922344 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-09 00:07:16.453305 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-09 00:07:16.496136 | 
2025-11-09 00:07:16.496341 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-09 00:07:17.054011 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.076832 | 
2025-11-09 00:07:17.077026 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-09 00:07:17.104273 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.113898 | 
2025-11-09 00:07:17.113997 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-09 00:07:17.139603 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.156827 | 
2025-11-09 00:07:17.156997 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-09 00:07:17.182003 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.190848 | 
2025-11-09 00:07:17.190944 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-09 00:07:17.215456 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.224448 | 
2025-11-09 00:07:17.224557 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-09 00:07:17.253235 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.273375 | 
2025-11-09 00:07:17.273479 | TASK [Disable Fedora Modular]
2025-11-09 00:07:17.572768 | controller | changed
2025-11-09 00:07:17.588309 | 
2025-11-09 00:07:17.588528 | TASK [Enable EPEL]
2025-11-09 00:07:17.616489 | controller | skipping: Conditional result was False
2025-11-09 00:07:17.632918 | 
2025-11-09 00:07:17.633156 | TASK [Register the RHEL node]
2025-11-09 00:07:18.200631 | 
2025-11-09 00:07:18.201016 | TASK [Show the subscription-manager status]
2025-11-09 00:07:18.763345 | controller | skipping: Conditional result was False
2025-11-09 00:07:18.778709 | 
2025-11-09 00:07:18.778906 | TASK [Enable EPEL on RHEL]
2025-11-09 00:07:19.343020 | controller | skipping: Conditional result was False
2025-11-09 00:07:19.358175 | 
2025-11-09 00:07:19.358343 | TASK [Install git and tox]
2025-11-09 00:08:49.806455 | controller | changed
2025-11-09 00:08:49.817827 | 
2025-11-09 00:08:49.817923 | TASK [include_role : prepare-workspace]
2025-11-09 00:08:49.841117 | controller | ok
2025-11-09 00:08:49.871160 | 
2025-11-09 00:08:49.871264 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-09 00:08:50.187100 | controller | ok
2025-11-09 00:08:50.198111 | 
2025-11-09 00:08:50.198213 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-09 00:09:03.727032 | controller | Output suppressed because no_log was given
2025-11-09 00:09:03.744330 | 
2025-11-09 00:09:03.744453 | TASK [include_role : prepare-workspace-openshift]
2025-11-09 00:09:03.780747 | controller | skipping: Conditional result was False
2025-11-09 00:09:03.813703 | 
2025-11-09 00:09:03.813801 | PLAY [all:!appliance]
2025-11-09 00:09:03.838551 | 
2025-11-09 00:09:03.838701 | TASK [Run add-build-sshkey role (RSA)]
2025-11-09 00:09:03.870542 | controller | ok
2025-11-09 00:09:03.885725 | 
2025-11-09 00:09:03.885797 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-09 00:09:04.174511 | controller -> localhost | ok
2025-11-09 00:09:04.181585 | 
2025-11-09 00:09:04.181652 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-09 00:09:04.217388 | controller | ok
2025-11-09 00:09:04.238905 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-09 00:09:04.248427 | 
2025-11-09 00:09:04.248700 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-09 00:09:04.928496 | controller -> localhost | Generating public/private rsa key pair.
2025-11-09 00:09:04.928948 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_rsa.
2025-11-09 00:09:04.929018 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_rsa.pub.
2025-11-09 00:09:04.929067 | controller -> localhost | The key fingerprint is:
2025-11-09 00:09:04.929113 | controller -> localhost | SHA256:PMiW79kfR6G6Mgx5fjo+6TQMdc9FX84T786VHQiTD1Y zuul-build-sshkey
2025-11-09 00:09:04.929157 | controller -> localhost | The key's randomart image is:
2025-11-09 00:09:04.929198 | controller -> localhost | +---[RSA 2048]----+
2025-11-09 00:09:04.929239 | controller -> localhost | |           ooE...|
2025-11-09 00:09:04.929282 | controller -> localhost | |           +o..++|
2025-11-09 00:09:04.929324 | controller -> localhost | |        . o o.oo=|
2025-11-09 00:09:04.929365 | controller -> localhost | |     . = . o + o=|
2025-11-09 00:09:04.929406 | controller -> localhost | |      *.S   + ..+|
2025-11-09 00:09:04.929472 | controller -> localhost | |     .o+.. . . o.|
2025-11-09 00:09:04.929522 | controller -> localhost | |       ==.. . . o|
2025-11-09 00:09:04.929565 | controller -> localhost | |       oO+.. o   |
2025-11-09 00:09:04.929606 | controller -> localhost | |       o*Bo..    |
2025-11-09 00:09:04.929655 | controller -> localhost | +----[SHA256]-----+
2025-11-09 00:09:04.929836 | controller -> localhost | ok: Runtime: 0:00:00.176274
2025-11-09 00:09:04.947523 | 
2025-11-09 00:09:04.947851 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-09 00:09:04.981605 | controller | ok
2025-11-09 00:09:05.003602 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-09 00:09:05.016963 | 
2025-11-09 00:09:05.017136 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-09 00:09:05.053571 | controller | skipping: Conditional result was False
2025-11-09 00:09:05.063246 | 
2025-11-09 00:09:05.063335 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-09 00:09:05.525838 | controller | changed
2025-11-09 00:09:05.540771 | 
2025-11-09 00:09:05.540957 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-09 00:09:05.796960 | controller | ok
2025-11-09 00:09:05.810634 | 
2025-11-09 00:09:05.810990 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-09 00:09:06.479629 | controller | changed
2025-11-09 00:09:06.536395 | 
2025-11-09 00:09:06.536564 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-09 00:09:07.173149 | controller | changed
2025-11-09 00:09:07.181371 | 
2025-11-09 00:09:07.181465 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-09 00:09:07.206743 | controller | skipping: Conditional result was False
2025-11-09 00:09:07.216953 | 
2025-11-09 00:09:07.217102 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-09 00:09:07.588322 | controller -> localhost | changed
2025-11-09 00:09:07.600735 | 
2025-11-09 00:09:07.600833 | TASK [add-build-sshkey : Add back temp key]
2025-11-09 00:09:07.890615 | controller -> localhost | Identity added: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_rsa (zuul-build-sshkey)
2025-11-09 00:09:07.890849 | controller -> localhost | ok: Runtime: 0:00:00.012979
2025-11-09 00:09:07.897820 | 
2025-11-09 00:09:07.897894 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-09 00:09:08.191704 | controller | ok
2025-11-09 00:09:08.197123 | 
2025-11-09 00:09:08.197186 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-09 00:09:08.221823 | controller | skipping: Conditional result was False
2025-11-09 00:09:08.249829 | 
2025-11-09 00:09:08.249979 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-09 00:09:08.282231 | controller | ok
2025-11-09 00:09:08.303942 | 
2025-11-09 00:09:08.304039 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-09 00:09:08.633831 | controller -> localhost | ok
2025-11-09 00:09:08.643777 | 
2025-11-09 00:09:08.643889 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-09 00:09:08.680776 | controller | ok
2025-11-09 00:09:08.697050 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-09 00:09:08.706915 | 
2025-11-09 00:09:08.707043 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-09 00:09:08.995910 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-09 00:09:08.996158 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_ecdsa.
2025-11-09 00:09:08.996189 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_ecdsa.pub.
2025-11-09 00:09:08.996219 | controller -> localhost | The key fingerprint is:
2025-11-09 00:09:08.996240 | controller -> localhost | SHA256:L/d5q+iHl3hLkH76k9E3EsgzIJAvaa1pzo+BeW+ykOQ zuul-build-sshkey
2025-11-09 00:09:08.996259 | controller -> localhost | The key's randomart image is:
2025-11-09 00:09:08.996278 | controller -> localhost | +---[ECDSA 521]---+
2025-11-09 00:09:08.996296 | controller -> localhost | |     .o          |
2025-11-09 00:09:08.996313 | controller -> localhost | |     . . .       |
2025-11-09 00:09:08.996331 | controller -> localhost | |      + . o .    |
2025-11-09 00:09:08.996348 | controller -> localhost | |     + o   * .   |
2025-11-09 00:09:08.996365 | controller -> localhost | |   .. + S o o..  |
2025-11-09 00:09:08.996382 | controller -> localhost | |  o ++   o ......|
2025-11-09 00:09:08.996399 | controller -> localhost | |   E+o  . +oo+...|
2025-11-09 00:09:08.996415 | controller -> localhost | |    o++. oo*B..  |
2025-11-09 00:09:08.996432 | controller -> localhost | |     o=o .+=*=.. |
2025-11-09 00:09:08.996449 | controller -> localhost | +----[SHA256]-----+
2025-11-09 00:09:08.996502 | controller -> localhost | ok: Runtime: 0:00:00.008500
2025-11-09 00:09:09.003105 | 
2025-11-09 00:09:09.003168 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-09 00:09:09.036443 | controller | ok
2025-11-09 00:09:09.046988 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-09 00:09:09.057177 | 
2025-11-09 00:09:09.057262 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-09 00:09:09.093360 | controller | skipping: Conditional result was False
2025-11-09 00:09:09.100940 | 
2025-11-09 00:09:09.101029 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-09 00:09:09.388648 | controller | changed
2025-11-09 00:09:09.395244 | 
2025-11-09 00:09:09.395335 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-09 00:09:09.637187 | controller | ok
2025-11-09 00:09:09.652612 | 
2025-11-09 00:09:09.652799 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-09 00:09:10.326279 | controller | changed
2025-11-09 00:09:10.339687 | 
2025-11-09 00:09:10.339852 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-09 00:09:11.041428 | controller | changed
2025-11-09 00:09:11.057284 | 
2025-11-09 00:09:11.057461 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-09 00:09:11.085137 | controller | skipping: Conditional result was False
2025-11-09 00:09:11.101515 | 
2025-11-09 00:09:11.101735 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-09 00:09:11.388984 | controller -> localhost | changed
2025-11-09 00:09:11.417245 | 
2025-11-09 00:09:11.417777 | TASK [add-build-sshkey : Add back temp key]
2025-11-09 00:09:11.770559 | controller -> localhost | Identity added: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/fdaa60f417b54405be4beeb8f70427df_id_ecdsa (zuul-build-sshkey)
2025-11-09 00:09:11.770844 | controller -> localhost | ok: Runtime: 0:00:00.014698
2025-11-09 00:09:11.778116 | 
2025-11-09 00:09:11.778182 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-09 00:09:12.017425 | controller | ok
2025-11-09 00:09:12.031336 | 
2025-11-09 00:09:12.031495 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-09 00:09:12.079176 | controller | skipping: Conditional result was False
2025-11-09 00:09:12.097512 | 
2025-11-09 00:09:12.097641 | TASK [include_role : remove-zuul-sshkey]
2025-11-09 00:09:12.125023 | controller | skipping: Conditional result was False
2025-11-09 00:09:12.135038 | 
2025-11-09 00:09:12.135140 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-09 00:09:12.371625 | controller | ok: "logs"
2025-11-09 00:09:12.372013 | controller | ok: All items complete
2025-11-09 00:09:12.372055 | 
2025-11-09 00:09:12.596602 | controller | ok: "artifacts"
2025-11-09 00:09:12.793857 | controller | ok: "docs"
2025-11-09 00:09:12.817316 | 
2025-11-09 00:09:12.817653 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-09 00:09:13.093052 | controller | changed: "logs"
2025-11-09 00:09:13.272136 | controller | changed: "artifacts"
2025-11-09 00:09:13.478877 | controller | changed: "docs"
2025-11-09 00:09:13.536100 | 
2025-11-09 00:09:13.536843 | PLAY RECAP
2025-11-09 00:09:13.536921 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-09 00:09:13.536960 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-09 00:09:13.536984 | 
2025-11-09 00:09:13.663776 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-09 00:09:13.666867 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-09 00:09:14.244712 | 
2025-11-09 00:09:14.244838 | PLAY [all]
2025-11-09 00:09:14.266960 | 
2025-11-09 00:09:14.267052 | TASK [Install binary dependencies]
2025-11-09 00:09:14.339199 | controller | ok
2025-11-09 00:09:14.392602 | 
2025-11-09 00:09:14.392736 | TASK [bindep : Include find tasks]
2025-11-09 00:09:14.439544 | controller | ok
2025-11-09 00:09:14.458416 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-09 00:09:14.471536 | 
2025-11-09 00:09:14.471621 | TASK [bindep : Look for bindep.txt]
2025-11-09 00:09:14.896362 | controller | ok
2025-11-09 00:09:14.908913 | 
2025-11-09 00:09:14.909058 | TASK [bindep : Define bindep_file fact]
2025-11-09 00:09:14.936542 | controller | skipping: Conditional result was False
2025-11-09 00:09:14.950457 | 
2025-11-09 00:09:14.950615 | TASK [bindep : Look for other-requirements.txt]
2025-11-09 00:09:15.179219 | controller | ok
2025-11-09 00:09:15.187242 | 
2025-11-09 00:09:15.187371 | TASK [bindep : Define bindep_file fact]
2025-11-09 00:09:15.224264 | controller | skipping: Conditional result was False
2025-11-09 00:09:15.233513 | 
2025-11-09 00:09:15.233659 | TASK [bindep : Look for bindep fallback file]
2025-11-09 00:09:15.281242 | controller | skipping: Conditional result was False
2025-11-09 00:09:15.299059 | 
2025-11-09 00:09:15.299298 | TASK [bindep : Define bindep_file fact]
2025-11-09 00:09:15.328018 | controller | skipping: Conditional result was False
2025-11-09 00:09:15.343921 | 
2025-11-09 00:09:15.344090 | TASK [bindep : Include bindep tasks]
2025-11-09 00:09:15.382383 | controller | skipping: Conditional result was False
2025-11-09 00:09:15.398493 | 
2025-11-09 00:09:15.398706 | TASK [bindep : Include install tasks]
2025-11-09 00:09:15.437782 | controller | skipping: Conditional result was False
2025-11-09 00:09:15.456980 | 
2025-11-09 00:09:15.457211 | LOOP [bindep : Include package tasks]
2025-11-09 00:09:15.555376 | 
2025-11-09 00:09:15.555635 | TASK [Run test-setup role]
2025-11-09 00:09:15.583496 | controller | ok
2025-11-09 00:09:15.612134 | 
2025-11-09 00:09:15.612309 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-09 00:09:15.826537 | controller | ok
2025-11-09 00:09:15.842307 | 
2025-11-09 00:09:15.842512 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-09 00:09:16.393466 | controller | skipping: Conditional result was False
2025-11-09 00:09:16.451386 | 
2025-11-09 00:09:16.451518 | PLAY RECAP
2025-11-09 00:09:16.451575 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-09 00:09:16.451604 | 
2025-11-09 00:09:16.577979 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-09 00:09:16.579515 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-09 00:09:17.185430 | 
2025-11-09 00:09:17.185562 | PLAY [controller]
2025-11-09 00:09:17.207061 | 
2025-11-09 00:09:17.207141 | TASK [Create the /root directory]
2025-11-09 00:09:17.613327 | controller | ok
2025-11-09 00:09:17.627462 | 
2025-11-09 00:09:17.627710 | TASK [Install glibc-langpack-en]
2025-11-09 00:09:21.377548 | controller | ok: Nothing to do
2025-11-09 00:09:21.386462 | 
2025-11-09 00:09:21.386566 | TASK [Ensure controller directory exists]
2025-11-09 00:09:21.608840 | controller | changed
2025-11-09 00:09:21.621607 | 
2025-11-09 00:09:21.621770 | TASK [Install container runtime]
2025-11-09 00:09:21.703280 | controller | ok
2025-11-09 00:09:21.769934 | 
2025-11-09 00:09:21.770147 | LOOP [ensure-podman : Find distribution installation]
2025-11-09 00:09:21.818064 | controller | ok: "/var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-09 00:09:21.846461 | controller | included: /var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-09 00:09:21.866840 | 
2025-11-09 00:09:21.867039 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-09 00:10:29.091357 | controller | changed
2025-11-09 00:10:29.105987 | 
2025-11-09 00:10:29.106127 | TASK [ensure-podman : Fetch podman version]
2025-11-09 00:10:29.735035 | controller | Client:       Podman Engine
2025-11-09 00:10:29.735204 | controller | Version:      4.6.2
2025-11-09 00:10:29.735280 | controller | API Version:  4.6.2
2025-11-09 00:10:29.735347 | controller | Go Version:   go1.19.12
2025-11-09 00:10:29.735432 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-09 00:10:29.735539 | controller | OS/Arch:      linux/amd64
2025-11-09 00:10:30.159374 | controller | ok: Runtime: 0:00:00.235497
2025-11-09 00:10:30.173348 | 
2025-11-09 00:10:30.173516 | TASK [ensure-podman : Print podman version installed]
2025-11-09 00:10:30.213114 | Podman version: Client:       Podman Engine
2025-11-09 00:10:30.213381 | Version:      4.6.2
2025-11-09 00:10:30.213442 | API Version:  4.6.2
2025-11-09 00:10:30.213486 | Go Version:   go1.19.12
2025-11-09 00:10:30.213526 | Built:        Mon Aug 28 19:38:31 2023
2025-11-09 00:10:30.213568 | OS/Arch:      linux/amd64
2025-11-09 00:10:30.226232 | 
2025-11-09 00:10:30.226366 | TASK [ensure-podman : Validate podman engine]
2025-11-09 00:10:30.774913 | controller | skipping: Conditional result was False
2025-11-09 00:10:30.789011 | 
2025-11-09 00:10:30.789150 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-09 00:10:30.816901 | controller | skipping: Conditional result was False
2025-11-09 00:10:30.842334 | 
2025-11-09 00:10:30.842626 | TASK [Ensure python3.8 is present]
2025-11-09 00:10:30.870178 | controller | skipping: Conditional result was False
2025-11-09 00:10:30.883303 | 
2025-11-09 00:10:30.883437 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-09 00:10:30.916201 | controller | ok
2025-11-09 00:10:30.945862 | 
2025-11-09 00:10:30.945960 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-09 00:10:32.629293 | controller | ok: Nothing to do
2025-11-09 00:10:32.642764 | 
2025-11-09 00:10:32.642899 | TASK [our-ensure-python : Also install python3-devel]
2025-11-09 00:10:42.206280 | controller | changed
2025-11-09 00:10:42.217297 | 
2025-11-09 00:10:42.217499 | TASK [Run ensure-virtualenv role]
2025-11-09 00:10:42.240725 | controller | ok
2025-11-09 00:10:42.264347 | 
2025-11-09 00:10:42.264462 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-09 00:10:42.487193 | controller | /usr/bin/virtualenv
2025-11-09 00:10:42.795276 | controller | ok: Runtime: 0:00:00.006662
2025-11-09 00:10:42.803163 | 
2025-11-09 00:10:42.803247 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-09 00:10:42.823485 | controller | skipping: Conditional result was False
2025-11-09 00:10:42.823779 | controller | ok: All items complete
2025-11-09 00:10:42.823808 | 
2025-11-09 00:10:42.843214 | 
2025-11-09 00:10:42.843356 | TASK [Find the full path of the Python interpreter]
2025-11-09 00:10:43.065106 | controller | /usr/bin/python3
2025-11-09 00:10:43.386497 | controller | ok
2025-11-09 00:10:43.400156 | 
2025-11-09 00:10:43.400303 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-09 00:10:44.350543 | controller | created virtual environment CPython3.11.0.final.0-64 in 549ms
2025-11-09 00:10:44.396352 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-09 00:10:44.397041 | 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/.local/share/virtualenv)
2025-11-09 00:10:44.397227 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-09 00:10:44.397252 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-09 00:10:44.461533 | controller | changed
2025-11-09 00:10:44.471128 | 
2025-11-09 00:10:44.471245 | TASK [Set selinux package]
2025-11-09 00:10:44.495285 | controller | ok
2025-11-09 00:10:44.503141 | 
2025-11-09 00:10:44.503229 | TASK [Set selinux package (Fedora)]
2025-11-09 00:10:44.536641 | controller | ok
2025-11-09 00:10:44.544700 | 
2025-11-09 00:10:44.544788 | TASK [Install selinux into virtualenv]
2025-11-09 00:10:58.190933 | controller | Collecting selinux-please-lie-to-me
2025-11-09 00:11:10.440637 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-09 00:11:10.773736 | controller | Collecting setuptools<50.0.0
2025-11-09 00:11:10.779943 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-09 00:11:10.822969 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 20.1 MB/s eta 0:00:00
2025-11-09 00:11:10.903355 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-09 00:11:10.903495 | controller |   Attempting uninstall: setuptools
2025-11-09 00:11:10.905944 | controller |     Found existing installation: setuptools 62.6.0
2025-11-09 00:11:10.967050 | controller |     Uninstalling setuptools-62.6.0:
2025-11-09 00:11:10.975112 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-09 00:11:11.344516 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-09 00:11:22.807396 | controller |
2025-11-09 00:11:22.890106 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-09 00:11:22.890155 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-09 00:11:23.125146 | controller | ok: Runtime: 0:00:38.073994
2025-11-09 00:11:23.134352 | 
2025-11-09 00:11:23.134513 | TASK [Install pytest-forked into virtualenv]
2025-11-09 00:11:35.053849 | controller | Collecting pytest-forked
2025-11-09 00:11:47.345729 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-09 00:11:47.395898 | controller | Collecting py
2025-11-09 00:11:47.400980 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-09 00:11:47.435431 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-11-09 00:11:47.546750 | controller | Collecting pytest>=3.10
2025-11-09 00:11:47.552322 | controller |   Downloading pytest-9.0.0-py3-none-any.whl (373 kB)
2025-11-09 00:11:47.568873 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.4/373.4 kB 27.0 MB/s eta 0:00:00
2025-11-09 00:11:47.612813 | controller | Collecting iniconfig>=1.0.1
2025-11-09 00:11:47.617338 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-09 00:11:47.657316 | controller | Collecting packaging>=22
2025-11-09 00:11:47.661158 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-09 00:11:47.672654 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.9 MB/s eta 0:00:00
2025-11-09 00:11:47.703901 | controller | Collecting pluggy<2,>=1.5
2025-11-09 00:11:47.707618 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-09 00:11:47.755961 | controller | Collecting pygments>=2.7.2
2025-11-09 00:11:47.760371 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-09 00:11:47.782949 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 61.8 MB/s eta 0:00:00
2025-11-09 00:11:47.851039 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-09 00:11:48.949340 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.0 pytest-forked-1.6.0
2025-11-09 00:11:48.958344 | controller |
2025-11-09 00:11:49.038321 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-09 00:11:49.038365 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-09 00:11:49.197935 | controller | ok: Runtime: 0:00:25.693238
2025-11-09 00:11:49.215173 | 
2025-11-09 00:11:49.215368 | TASK [Update pip]
2025-11-09 00:11:49.795750 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-09 00:11:59.687598 | controller | Collecting pip
2025-11-09 00:12:11.900415 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-09 00:12:11.969894 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 28.5 MB/s eta 0:00:00
2025-11-09 00:12:12.037563 | controller | Installing collected packages: pip
2025-11-09 00:12:12.037733 | controller |   Attempting uninstall: pip
2025-11-09 00:12:12.039970 | controller |     Found existing installation: pip 22.2.2
2025-11-09 00:12:12.183980 | controller |     Uninstalling pip-22.2.2:
2025-11-09 00:12:12.199285 | controller |       Successfully uninstalled pip-22.2.2
2025-11-09 00:12:13.042799 | controller | Successfully installed pip-25.3
2025-11-09 00:12:13.325456 | controller | ok: Runtime: 0:00:23.629569
2025-11-09 00:12:13.350229 | 
2025-11-09 00:12:13.350684 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-09 00:12:13.588320 | controller | changed
2025-11-09 00:12:13.600243 | 
2025-11-09 00:12:13.600402 | TASK [Install ansible into virtualenv]
2025-11-09 00:12:14.095152 | controller | Processing ./src/github.com/ansible/ansible
2025-11-09 00:12:14.098299 | controller |   Installing build dependencies: started
2025-11-09 00:12:37.068165 | controller |   Installing build dependencies: finished with status 'done'
2025-11-09 00:12:37.068248 | controller |   Getting requirements to build wheel: started
2025-11-09 00:12:37.819006 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-09 00:12:37.820002 | controller |   Preparing metadata (pyproject.toml): started
2025-11-09 00:12:38.296180 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-09 00:12:38.298664 | 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-11-09 00:12:38.301192 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-09 00:12:38.662850 | controller | ERROR
2025-11-09 00:12:38.663186 | controller | {
2025-11-09 00:12:38.663248 | controller |   "delta": "0:00:24.544150",
2025-11-09 00:12:38.663290 | controller |   "end": "2025-11-09 00:12:38.362562",
2025-11-09 00:12:38.663326 | controller |   "msg": "non-zero return code",
2025-11-09 00:12:38.663385 | controller |   "rc": 1,
2025-11-09 00:12:38.663421 | controller |   "start": "2025-11-09 00:12:13.818412"
2025-11-09 00:12:38.663455 | controller | }
failure
2025-11-09 00:12:38.666184 | 
2025-11-09 00:12:38.666280 | PLAY RECAP
2025-11-09 00:12:38.666365 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-09 00:12:38.666407 | 
2025-11-09 00:12:38.826142 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-09 00:12:38.827578 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-09 00:12:39.442018 | 
2025-11-09 00:12:39.442150 | PLAY [all]
2025-11-09 00:12:39.465360 | 
2025-11-09 00:12:39.465459 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-09 00:12:39.753159 | controller | changed: non-zero return code
2025-11-09 00:12:39.768131 | 
2025-11-09 00:12:39.768449 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-09 00:12:39.798417 | controller | skipping: Conditional result was False
2025-11-09 00:12:39.811576 | 
2025-11-09 00:12:39.811891 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-09 00:12:39.851518 | 
2025-11-09 00:12:39.851823 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-09 00:12:39.887631 | 
2025-11-09 00:12:39.887949 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-09 00:12:39.914345 | controller | skipping: Conditional result was False
2025-11-09 00:12:39.925361 | 
2025-11-09 00:12:39.925485 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-09 00:12:39.970998 | 
2025-11-09 00:12:39.971234 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-09 00:12:39.997790 | controller | skipping: Conditional result was False
2025-11-09 00:12:40.007037 | 
2025-11-09 00:12:40.007169 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-09 00:12:40.033359 | controller | skipping: Conditional result was False
2025-11-09 00:12:40.042817 | 
2025-11-09 00:12:40.042996 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-09 00:12:40.068597 | controller | skipping: Conditional result was False
2025-11-09 00:12:40.106916 | 
2025-11-09 00:12:40.107023 | PLAY RECAP
2025-11-09 00:12:40.107064 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-09 00:12:40.107084 | 
2025-11-09 00:12:40.225758 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-09 00:12:40.228287 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-09 00:12:40.893639 | 
2025-11-09 00:12:40.893816 | PLAY [all:!appliance*]
2025-11-09 00:12:40.916608 | 
2025-11-09 00:12:40.916839 | TASK [unregister the node]
2025-11-09 00:12:41.450465 | controller | skipping: Conditional result was False
2025-11-09 00:12:41.466466 | 
2025-11-09 00:12:41.467122 | TASK [include_role : fetch-output]
2025-11-09 00:12:41.519426 | controller | ok
2025-11-09 00:12:41.560984 | 
2025-11-09 00:12:41.561109 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-09 00:12:41.638287 | controller | skipping: Conditional result was False
2025-11-09 00:12:41.648408 | 
2025-11-09 00:12:41.648509 | TASK [fetch-output : Set log path for single node]
2025-11-09 00:12:41.713448 | controller | ok
2025-11-09 00:12:41.721296 | 
2025-11-09 00:12:41.721383 | LOOP [fetch-output : Ensure local output dirs]
2025-11-09 00:12:42.184927 | controller -> localhost | ok: "/var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/logs"
2025-11-09 00:12:42.490328 | controller -> localhost | changed: "/var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/artifacts"
2025-11-09 00:12:42.781353 | controller -> localhost | changed: "/var/lib/zuul/builds/fdaa60f417b54405be4beeb8f70427df/work/docs"
2025-11-09 00:12:42.798946 | 
2025-11-09 00:12:42.799114 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-09 00:12:43.598647 | controller | changed:
2025-11-09 00:12:43.599081 | controller | .d..t...... ./
2025-11-09 00:12:43.599140 | controller | cd+++++++++ controller/
2025-11-09 00:12:43.599208 | controller | changed: All items complete
2025-11-09 00:12:43.599252 | 
2025-11-09 00:12:44.173393 | controller | changed: .d..t...... ./
2025-11-09 00:12:44.680169 | controller | changed: .d..t...... ./
2025-11-09 00:12:44.708397 | 
2025-11-09 00:12:44.708543 | TASK [include_role : fetch-output-openshift]
2025-11-09 00:12:44.754217 | controller | skipping: Conditional result was False
2025-11-09 00:12:44.764150 | 
2025-11-09 00:12:44.764251 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-09 00:12:44.793962 | controller | skipping: Conditional result was False
2025-11-09 00:12:44.801845 | controller | skipping: Conditional result was False
2025-11-09 00:12:44.857487 | 
2025-11-09 00:12:44.857617 | PLAY [localhost]
2025-11-09 00:12:44.885368 | 
2025-11-09 00:12:44.885542 | TASK [Run Zuul manifest role]
2025-11-09 00:12:44.907791 | localhost | ok
2025-11-09 00:12:44.928739 | 
2025-11-09 00:12:44.928892 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-09 00:12:45.367396 | localhost | changed
2025-11-09 00:12:45.384586 | 
2025-11-09 00:12:45.384851 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-09 00:12:45.413432 | localhost | ok
2025-11-09 00:12:45.421677 | 
2025-11-09 00:12:45.421737 | TASK [Set zuul-log-path fact]
2025-11-09 00:12:45.439791 | localhost | ok
2025-11-09 00:12:45.453196 | 
2025-11-09 00:12:45.453270 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-09 00:12:45.481547 | localhost | ok
2025-11-09 00:12:45.490122 | 
2025-11-09 00:12:45.490187 | LOOP [Run upload-logs-swift role]
2025-11-09 00:12:45.513768 | localhost | Output suppressed because no_log was given
2025-11-09 00:12:45.539451 | 
2025-11-09 00:12:45.539566 | TASK [Set zuul-log-path fact]
2025-11-09 00:12:45.609488 | localhost | skipping: Conditional result was False
2025-11-09 00:12:45.646084 | 
2025-11-09 00:12:45.646210 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-09 00:12:46.005477 | localhost -> localhost | ok: Runtime: 0:00:00.012347
2025-11-09 00:12:46.026305 | 
2025-11-09 00:12:46.026482 | TASK [upload-logs-swift : Upload logs to swift]