2025-11-13 00:24:46.283584 | Job console starting...
2025-11-13 00:24:46.293360 | Updating repositories
2025-11-13 00:24:46.421885 | Preparing job workspace
2025-11-13 00:24:50.190249 | Running Ansible setup...
2025-11-13 00:24:57.477206 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-13 00:24:58.190529 | 
2025-11-13 00:24:58.190660 | PLAY [localhost]
2025-11-13 00:24:58.200815 | 
2025-11-13 00:24:58.200975 | TASK [Gathering Facts]
2025-11-13 00:24:59.256786 | localhost | ok
2025-11-13 00:24:59.280870 | 
2025-11-13 00:24:59.281028 | TASK [Setup log path fact]
2025-11-13 00:24:59.307725 | localhost | ok
2025-11-13 00:24:59.333933 | 
2025-11-13 00:24:59.334085 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-13 00:24:59.375474 | localhost | ok
2025-11-13 00:24:59.387443 | 
2025-11-13 00:24:59.387540 | TASK [emit-job-header : Print job information]
2025-11-13 00:24:59.439122 | # Job Information
2025-11-13 00:24:59.439299 | Ansible Version: 2.15.12
2025-11-13 00:24:59.439344 | Job: ansible-test-sanity-docker-milestone
2025-11-13 00:24:59.439381 | Pipeline: periodic
2025-11-13 00:24:59.439408 | Executor: ze02.softwarefactory-project.io
2025-11-13 00:24:59.439434 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-13 00:24:59.439464 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/dc5/ansible/dc51013698014064ad9653b7e8551f82/
2025-11-13 00:24:59.439492 | Event ID: 81b75bab06fd44ecba554c97b6c93ff4
2025-11-13 00:24:59.445063 | 
2025-11-13 00:24:59.445155 | LOOP [emit-job-header : Print node information]
2025-11-13 00:24:59.563391 | localhost | ok:
2025-11-13 00:24:59.563642 | localhost | # Node Information
2025-11-13 00:24:59.563708 | localhost | Inventory Hostname: controller
2025-11-13 00:24:59.563738 | localhost | Hostname: np0005520538
2025-11-13 00:24:59.563765 | localhost | Username: zuul
2025-11-13 00:24:59.563802 | localhost | Distro: Fedora 37
2025-11-13 00:24:59.563829 | localhost | Provider: ansible-vexxhost-ams1
2025-11-13 00:24:59.563854 | localhost | Region: ams1
2025-11-13 00:24:59.563879 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-13 00:24:59.563903 | localhost | Product Name: OpenStack Nova
2025-11-13 00:24:59.563957 | localhost | Interface IP: 38.129.16.155
2025-11-13 00:24:59.576181 | 
2025-11-13 00:24:59.576270 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-13 00:25:00.012200 | localhost -> localhost | changed
2025-11-13 00:25:00.020278 | 
2025-11-13 00:25:00.020591 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-13 00:25:00.948951 | localhost -> localhost | changed
2025-11-13 00:25:00.990744 | 
2025-11-13 00:25:00.990865 | PLAY [all:!appliance*]
2025-11-13 00:25:01.013728 | 
2025-11-13 00:25:01.013835 | TASK [include_role : start-zuul-console]
2025-11-13 00:25:01.036539 | controller | ok
2025-11-13 00:25:01.055641 | 
2025-11-13 00:25:01.055783 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-13 00:25:02.047784 | controller | ok
2025-11-13 00:25:02.076242 | 
2025-11-13 00:25:02.076607 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-13 00:25:07.875776 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-13 00:25:07.890852 | 
2025-11-13 00:25:07.891040 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-13 00:25:08.264826 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.274461 | 
2025-11-13 00:25:08.274565 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-13 00:25:08.299562 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.309412 | 
2025-11-13 00:25:08.309514 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-13 00:25:08.335942 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.346340 | 
2025-11-13 00:25:08.346449 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-13 00:25:08.372513 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.381851 | 
2025-11-13 00:25:08.381949 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-13 00:25:08.408416 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.419477 | 
2025-11-13 00:25:08.419855 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-13 00:25:08.446280 | controller | skipping: Conditional result was False
2025-11-13 00:25:08.462947 | 
2025-11-13 00:25:08.463093 | TASK [Disable Fedora Modular]
2025-11-13 00:25:09.655859 | controller | changed
2025-11-13 00:25:09.664060 | 
2025-11-13 00:25:09.664150 | TASK [Enable EPEL]
2025-11-13 00:25:09.690361 | controller | skipping: Conditional result was False
2025-11-13 00:25:09.710763 | 
2025-11-13 00:25:09.711017 | TASK [Register the RHEL node]
2025-11-13 00:25:10.111518 | 
2025-11-13 00:25:10.111895 | TASK [Show the subscription-manager status]
2025-11-13 00:25:10.516643 | controller | skipping: Conditional result was False
2025-11-13 00:25:10.526802 | 
2025-11-13 00:25:10.526900 | TASK [Enable EPEL on RHEL]
2025-11-13 00:25:10.895740 | controller | skipping: Conditional result was False
2025-11-13 00:25:10.910696 | 
2025-11-13 00:25:10.910922 | TASK [Install git and tox]
2025-11-13 00:26:54.826954 | controller | changed
2025-11-13 00:26:54.846826 | 
2025-11-13 00:26:54.847029 | TASK [include_role : prepare-workspace]
2025-11-13 00:26:54.888037 | controller | ok
2025-11-13 00:26:54.925843 | 
2025-11-13 00:26:54.926121 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-13 00:26:55.740588 | controller | ok
2025-11-13 00:26:55.757973 | 
2025-11-13 00:26:55.758124 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-13 00:27:11.047135 | controller | Output suppressed because no_log was given
2025-11-13 00:27:11.078246 | 
2025-11-13 00:27:11.078368 | TASK [include_role : prepare-workspace-openshift]
2025-11-13 00:27:11.109358 | controller | skipping: Conditional result was False
2025-11-13 00:27:11.162724 | 
2025-11-13 00:27:11.162874 | PLAY [all:!appliance]
2025-11-13 00:27:11.194046 | 
2025-11-13 00:27:11.194196 | TASK [Run add-build-sshkey role (RSA)]
2025-11-13 00:27:11.230036 | controller | ok
2025-11-13 00:27:11.254906 | 
2025-11-13 00:27:11.255088 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-13 00:27:11.550630 | controller -> localhost | ok
2025-11-13 00:27:11.558151 | 
2025-11-13 00:27:11.558242 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-13 00:27:11.590494 | controller | ok
2025-11-13 00:27:11.605330 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-13 00:27:11.611624 | 
2025-11-13 00:27:11.611712 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-13 00:27:12.076089 | controller -> localhost | Generating public/private rsa key pair.
2025-11-13 00:27:12.076422 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_rsa.
2025-11-13 00:27:12.076466 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_rsa.pub.
2025-11-13 00:27:12.076494 | controller -> localhost | The key fingerprint is:
2025-11-13 00:27:12.076520 | controller -> localhost | SHA256:GvWoSyO6pctw0/9blYSYLPo1kOgpgBnUspnbGbUPqWg zuul-build-sshkey
2025-11-13 00:27:12.076547 | controller -> localhost | The key's randomart image is:
2025-11-13 00:27:12.076586 | controller -> localhost | +---[RSA 2048]----+
2025-11-13 00:27:12.076615 | controller -> localhost | |o..              |
2025-11-13 00:27:12.076645 | controller -> localhost | |.+ . o o o .     |
2025-11-13 00:27:12.076701 | controller -> localhost | |+ = o * = . .    |
2025-11-13 00:27:12.076732 | controller -> localhost | | = o * + o . .   |
2025-11-13 00:27:12.076757 | controller -> localhost | |  = B + S . o    |
2025-11-13 00:27:12.076801 | controller -> localhost | | E * . * . .     |
2025-11-13 00:27:12.076837 | controller -> localhost | |o o + *   .      |
2025-11-13 00:27:12.076866 | controller -> localhost | | + = + o .       |
2025-11-13 00:27:12.076890 | controller -> localhost | |  *o  o.o.       |
2025-11-13 00:27:12.076918 | controller -> localhost | +----[SHA256]-----+
2025-11-13 00:27:12.077021 | controller -> localhost | ok: Runtime: 0:00:00.080428
2025-11-13 00:27:12.086207 | 
2025-11-13 00:27:12.086330 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-13 00:27:12.120518 | controller | ok
2025-11-13 00:27:12.135821 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-13 00:27:12.150549 | 
2025-11-13 00:27:12.150998 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-13 00:27:12.179057 | controller | skipping: Conditional result was False
2025-11-13 00:27:12.190106 | 
2025-11-13 00:27:12.190219 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-13 00:27:13.254619 | controller | changed
2025-11-13 00:27:13.269383 | 
2025-11-13 00:27:13.269570 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-13 00:27:13.905599 | controller | ok
2025-11-13 00:27:13.919474 | 
2025-11-13 00:27:13.919622 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-13 00:27:16.897471 | controller | changed
2025-11-13 00:27:16.910764 | 
2025-11-13 00:27:16.910904 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-13 00:27:19.866203 | controller | changed
2025-11-13 00:27:19.879627 | 
2025-11-13 00:27:19.879802 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-13 00:27:19.908405 | controller | skipping: Conditional result was False
2025-11-13 00:27:19.923524 | 
2025-11-13 00:27:19.923703 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-13 00:27:20.380063 | controller -> localhost | changed
2025-11-13 00:27:20.407727 | 
2025-11-13 00:27:20.407882 | TASK [add-build-sshkey : Add back temp key]
2025-11-13 00:27:20.711994 | controller -> localhost | Identity added: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_rsa (zuul-build-sshkey)
2025-11-13 00:27:20.712329 | controller -> localhost | ok: Runtime: 0:00:00.008366
2025-11-13 00:27:20.727161 | 
2025-11-13 00:27:20.727310 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-13 00:27:21.608422 | controller | ok
2025-11-13 00:27:21.617580 | 
2025-11-13 00:27:21.617742 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-13 00:27:21.646173 | controller | skipping: Conditional result was False
2025-11-13 00:27:21.669542 | 
2025-11-13 00:27:21.669640 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-13 00:27:21.702865 | controller | ok
2025-11-13 00:27:21.725681 | 
2025-11-13 00:27:21.725821 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-13 00:27:22.026976 | controller -> localhost | ok
2025-11-13 00:27:22.044314 | 
2025-11-13 00:27:22.044466 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-13 00:27:22.084957 | controller | ok
2025-11-13 00:27:22.108917 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-13 00:27:22.117933 | 
2025-11-13 00:27:22.118020 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-13 00:27:22.460585 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-13 00:27:22.460863 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_ecdsa.
2025-11-13 00:27:22.460902 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_ecdsa.pub.
2025-11-13 00:27:22.460941 | controller -> localhost | The key fingerprint is:
2025-11-13 00:27:22.460967 | controller -> localhost | SHA256:lZO6S6xNJ29aUM7imX7n+bNJYyLj7BZjTXmUVJM1Kj4 zuul-build-sshkey
2025-11-13 00:27:22.460991 | controller -> localhost | The key's randomart image is:
2025-11-13 00:27:22.461016 | controller -> localhost | +---[ECDSA 521]---+
2025-11-13 00:27:22.461040 | controller -> localhost | |             ..==|
2025-11-13 00:27:22.461063 | controller -> localhost | |           o  +.o|
2025-11-13 00:27:22.461086 | controller -> localhost | |          *. +   |
2025-11-13 00:27:22.461109 | controller -> localhost | |         *..+ .  |
2025-11-13 00:27:22.461132 | controller -> localhost | |        S oE .   |
2025-11-13 00:27:22.461154 | controller -> localhost | |       o *+ o    |
2025-11-13 00:27:22.461176 | controller -> localhost | |        X.=o. +  |
2025-11-13 00:27:22.461198 | controller -> localhost | |       * O+o.=.o |
2025-11-13 00:27:22.461219 | controller -> localhost | |      . =*=oo.+o |
2025-11-13 00:27:22.461241 | controller -> localhost | +----[SHA256]-----+
2025-11-13 00:27:22.461305 | controller -> localhost | ok: Runtime: 0:00:00.016115
2025-11-13 00:27:22.470885 | 
2025-11-13 00:27:22.470974 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-13 00:27:22.506312 | controller | ok
2025-11-13 00:27:22.554713 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-13 00:27:22.564322 | 
2025-11-13 00:27:22.564404 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-13 00:27:22.589452 | controller | skipping: Conditional result was False
2025-11-13 00:27:22.596414 | 
2025-11-13 00:27:22.596488 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-13 00:27:23.456486 | controller | changed
2025-11-13 00:27:23.472274 | 
2025-11-13 00:27:23.472431 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-13 00:27:24.107963 | controller | ok
2025-11-13 00:27:24.121876 | 
2025-11-13 00:27:24.122030 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-13 00:27:27.071297 | controller | changed
2025-11-13 00:27:27.084259 | 
2025-11-13 00:27:27.084405 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-13 00:27:30.032436 | controller | changed
2025-11-13 00:27:30.045756 | 
2025-11-13 00:27:30.045898 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-13 00:27:30.083650 | controller | skipping: Conditional result was False
2025-11-13 00:27:30.096959 | 
2025-11-13 00:27:30.097100 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-13 00:27:30.450231 | controller -> localhost | changed
2025-11-13 00:27:30.477070 | 
2025-11-13 00:27:30.477273 | TASK [add-build-sshkey : Add back temp key]
2025-11-13 00:27:30.780811 | controller -> localhost | Identity added: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/dc51013698014064ad9653b7e8551f82_id_ecdsa (zuul-build-sshkey)
2025-11-13 00:27:30.781131 | controller -> localhost | ok: Runtime: 0:00:00.012534
2025-11-13 00:27:30.788757 | 
2025-11-13 00:27:30.788823 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-13 00:27:31.444591 | controller | ok
2025-11-13 00:27:31.453156 | 
2025-11-13 00:27:31.453266 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-13 00:27:31.500036 | controller | skipping: Conditional result was False
2025-11-13 00:27:31.519499 | 
2025-11-13 00:27:31.519623 | TASK [include_role : remove-zuul-sshkey]
2025-11-13 00:27:31.546398 | controller | skipping: Conditional result was False
2025-11-13 00:27:31.557236 | 
2025-11-13 00:27:31.557340 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-13 00:27:32.197178 | controller | ok: "logs"
2025-11-13 00:27:32.197808 | controller | ok: All items complete
2025-11-13 00:27:32.197894 | 
2025-11-13 00:27:32.784091 | controller | ok: "artifacts"
2025-11-13 00:27:33.364786 | controller | ok: "docs"
2025-11-13 00:27:33.389743 | 
2025-11-13 00:27:33.389956 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-13 00:27:34.035912 | controller | changed: "logs"
2025-11-13 00:27:34.634935 | controller | changed: "artifacts"
2025-11-13 00:27:35.227786 | controller | changed: "docs"
2025-11-13 00:27:35.287554 | 
2025-11-13 00:27:35.287739 | PLAY RECAP
2025-11-13 00:27:35.287807 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-13 00:27:35.287842 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-13 00:27:35.287866 | 
2025-11-13 00:27:35.421119 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-13 00:27:35.422143 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-13 00:27:36.065204 | 
2025-11-13 00:27:36.065393 | PLAY [all]
2025-11-13 00:27:36.093585 | 
2025-11-13 00:27:36.093776 | TASK [Install binary dependencies]
2025-11-13 00:27:36.158140 | controller | ok
2025-11-13 00:27:36.185396 | 
2025-11-13 00:27:36.185515 | TASK [bindep : Include find tasks]
2025-11-13 00:27:36.229007 | controller | ok
2025-11-13 00:27:36.240077 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-13 00:27:36.249046 | 
2025-11-13 00:27:36.249132 | TASK [bindep : Look for bindep.txt]
2025-11-13 00:27:37.179906 | controller | ok
2025-11-13 00:27:37.197008 | 
2025-11-13 00:27:37.197214 | TASK [bindep : Define bindep_file fact]
2025-11-13 00:27:37.224959 | controller | skipping: Conditional result was False
2025-11-13 00:27:37.235487 | 
2025-11-13 00:27:37.235814 | TASK [bindep : Look for other-requirements.txt]
2025-11-13 00:27:37.835846 | controller | ok
2025-11-13 00:27:37.845942 | 
2025-11-13 00:27:37.846039 | TASK [bindep : Define bindep_file fact]
2025-11-13 00:27:37.872554 | controller | skipping: Conditional result was False
2025-11-13 00:27:37.884158 | 
2025-11-13 00:27:37.884363 | TASK [bindep : Look for bindep fallback file]
2025-11-13 00:27:37.921375 | controller | skipping: Conditional result was False
2025-11-13 00:27:37.933739 | 
2025-11-13 00:27:37.933960 | TASK [bindep : Define bindep_file fact]
2025-11-13 00:27:37.971466 | controller | skipping: Conditional result was False
2025-11-13 00:27:37.982373 | 
2025-11-13 00:27:37.982513 | TASK [bindep : Include bindep tasks]
2025-11-13 00:27:38.018232 | controller | skipping: Conditional result was False
2025-11-13 00:27:38.028384 | 
2025-11-13 00:27:38.028561 | TASK [bindep : Include install tasks]
2025-11-13 00:27:38.055321 | controller | skipping: Conditional result was False
2025-11-13 00:27:38.065893 | 
2025-11-13 00:27:38.066007 | LOOP [bindep : Include package tasks]
2025-11-13 00:27:38.141318 | 
2025-11-13 00:27:38.141603 | TASK [Run test-setup role]
2025-11-13 00:27:38.170362 | controller | ok
2025-11-13 00:27:38.203009 | 
2025-11-13 00:27:38.203175 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-13 00:27:38.877267 | controller | ok
2025-11-13 00:27:38.892485 | 
2025-11-13 00:27:38.892622 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-13 00:27:39.269578 | controller | skipping: Conditional result was False
2025-11-13 00:27:39.324025 | 
2025-11-13 00:27:39.324161 | PLAY RECAP
2025-11-13 00:27:39.324216 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-13 00:27:39.324244 | 
2025-11-13 00:27:39.461550 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-13 00:27:39.462537 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-13 00:27:40.156644 | 
2025-11-13 00:27:40.156829 | PLAY [controller]
2025-11-13 00:27:40.182099 | 
2025-11-13 00:27:40.182221 | TASK [Create the /root directory]
2025-11-13 00:27:41.142966 | controller | ok
2025-11-13 00:27:41.149188 | 
2025-11-13 00:27:41.149275 | TASK [Install glibc-langpack-en]
2025-11-13 00:27:48.321054 | controller | ok: Nothing to do
2025-11-13 00:27:48.335030 | 
2025-11-13 00:27:48.335171 | TASK [Ensure controller directory exists]
2025-11-13 00:27:49.140319 | controller | changed
2025-11-13 00:27:49.154891 | 
2025-11-13 00:27:49.155086 | TASK [Install container runtime]
2025-11-13 00:27:49.218641 | controller | ok
2025-11-13 00:27:49.279999 | 
2025-11-13 00:27:49.280201 | LOOP [ensure-podman : Find distribution installation]
2025-11-13 00:27:49.318428 | controller | ok: "/var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-13 00:27:49.336581 | controller | included: /var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-13 00:27:49.346244 | 
2025-11-13 00:27:49.346348 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-13 00:29:38.544329 | controller | changed
2025-11-13 00:29:38.561035 | 
2025-11-13 00:29:38.561185 | TASK [ensure-podman : Fetch podman version]
2025-11-13 00:29:39.626434 | controller | Client:       Podman Engine
2025-11-13 00:29:39.626542 | controller | Version:      4.6.2
2025-11-13 00:29:39.626587 | controller | API Version:  4.6.2
2025-11-13 00:29:39.626629 | controller | Go Version:   go1.19.12
2025-11-13 00:29:39.626690 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-13 00:29:39.626733 | controller | OS/Arch:      linux/amd64
2025-11-13 00:29:39.933813 | controller | ok: Runtime: 0:00:00.237272
2025-11-13 00:29:39.940869 | 
2025-11-13 00:29:39.940947 | TASK [ensure-podman : Print podman version installed]
2025-11-13 00:29:39.974001 | Podman version: Client:       Podman Engine
2025-11-13 00:29:39.974193 | Version:      4.6.2
2025-11-13 00:29:39.974231 | API Version:  4.6.2
2025-11-13 00:29:39.974256 | Go Version:   go1.19.12
2025-11-13 00:29:39.974275 | Built:        Mon Aug 28 19:38:31 2023
2025-11-13 00:29:39.974294 | OS/Arch:      linux/amd64
2025-11-13 00:29:39.983176 | 
2025-11-13 00:29:39.983309 | TASK [ensure-podman : Validate podman engine]
2025-11-13 00:29:40.342282 | controller | skipping: Conditional result was False
2025-11-13 00:29:40.357018 | 
2025-11-13 00:29:40.357194 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-13 00:29:40.384992 | controller | skipping: Conditional result was False
2025-11-13 00:29:40.412949 | 
2025-11-13 00:29:40.413149 | TASK [Ensure python3.8 is present]
2025-11-13 00:29:40.429388 | controller | skipping: Conditional result was False
2025-11-13 00:29:40.439504 | 
2025-11-13 00:29:40.439619 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-13 00:29:40.465465 | controller | ok
2025-11-13 00:29:40.496567 | 
2025-11-13 00:29:40.496765 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-13 00:29:43.658065 | controller | ok: Nothing to do
2025-11-13 00:29:43.673152 | 
2025-11-13 00:29:43.673394 | TASK [our-ensure-python : Also install python3-devel]
2025-11-13 00:29:57.227721 | controller | changed
2025-11-13 00:29:57.242379 | 
2025-11-13 00:29:57.242560 | TASK [Run ensure-virtualenv role]
2025-11-13 00:29:57.264450 | controller | ok
2025-11-13 00:29:57.284436 | 
2025-11-13 00:29:57.284553 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-13 00:29:58.032289 | controller | /usr/bin/virtualenv
2025-11-13 00:29:58.172849 | controller | ok: Runtime: 0:00:00.004705
2025-11-13 00:29:58.188108 | 
2025-11-13 00:29:58.188349 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-13 00:29:58.214353 | controller | skipping: Conditional result was False
2025-11-13 00:29:58.214738 | controller | ok: All items complete
2025-11-13 00:29:58.214781 | 
2025-11-13 00:29:58.231795 | 
2025-11-13 00:29:58.231927 | TASK [Find the full path of the Python interpreter]
2025-11-13 00:29:58.815921 | controller | /usr/bin/python3
2025-11-13 00:29:59.092925 | controller | ok
2025-11-13 00:29:59.106116 | 
2025-11-13 00:29:59.106264 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-13 00:30:00.784684 | controller | created virtual environment CPython3.11.0.final.0-64 in 830ms
2025-11-13 00:30:00.864663 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-13 00:30:00.864775 | 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-13 00:30:00.864791 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-13 00:30:00.864821 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-13 00:30:01.484834 | controller | changed
2025-11-13 00:30:01.500212 | 
2025-11-13 00:30:01.500405 | TASK [Set selinux package]
2025-11-13 00:30:01.541161 | controller | ok
2025-11-13 00:30:01.553892 | 
2025-11-13 00:30:01.554064 | TASK [Set selinux package (Fedora)]
2025-11-13 00:30:01.614622 | controller | ok
2025-11-13 00:30:01.625789 | 
2025-11-13 00:30:01.625917 | TASK [Install selinux into virtualenv]
2025-11-13 00:30:04.190597 | controller | Collecting selinux-please-lie-to-me
2025-11-13 00:30:04.246945 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-13 00:30:04.677151 | controller | Collecting setuptools<50.0.0
2025-11-13 00:30:04.682343 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-13 00:30:04.722929 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.2 MB/s eta 0:00:00
2025-11-13 00:30:04.842996 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-13 00:30:04.843327 | controller |   Attempting uninstall: setuptools
2025-11-13 00:30:04.847134 | controller |     Found existing installation: setuptools 62.6.0
2025-11-13 00:30:04.935031 | controller |     Uninstalling setuptools-62.6.0:
2025-11-13 00:30:04.947299 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-13 00:30:05.586474 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-13 00:30:05.763306 | controller |
2025-11-13 00:30:05.995326 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-13 00:30:05.995384 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-13 00:30:06.521366 | controller | ok: Runtime: 0:00:03.552179
2025-11-13 00:30:06.533234 | 
2025-11-13 00:30:06.533333 | TASK [Install pytest-forked into virtualenv]
2025-11-13 00:30:07.973867 | controller | Collecting pytest-forked
2025-11-13 00:30:08.024510 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-13 00:30:08.072297 | controller | Collecting py
2025-11-13 00:30:08.078240 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-13 00:30:08.101529 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.6 MB/s eta 0:00:00
2025-11-13 00:30:08.252068 | controller | Collecting pytest>=3.10
2025-11-13 00:30:08.256418 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-13 00:30:08.272659 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 28.5 MB/s eta 0:00:00
2025-11-13 00:30:08.317761 | controller | Collecting iniconfig>=1.0.1
2025-11-13 00:30:08.323028 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-13 00:30:08.374759 | controller | Collecting packaging>=22
2025-11-13 00:30:08.378621 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-13 00:30:08.386741 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.0 MB/s eta 0:00:00
2025-11-13 00:30:08.423018 | controller | Collecting pluggy<2,>=1.5
2025-11-13 00:30:08.426978 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-13 00:30:08.489149 | controller | Collecting pygments>=2.7.2
2025-11-13 00:30:08.493675 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-13 00:30:08.513706 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 73.2 MB/s eta 0:00:00
2025-11-13 00:30:08.613571 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-13 00:30:10.636444 | 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.1 pytest-forked-1.6.0
2025-11-13 00:30:10.657147 | controller |
2025-11-13 00:30:10.851256 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-13 00:30:10.851310 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-13 00:30:11.433353 | controller | ok: Runtime: 0:00:03.562078
2025-11-13 00:30:11.447044 | 
2025-11-13 00:30:11.447181 | TASK [Update pip]
2025-11-13 00:30:12.873623 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-13 00:30:13.109457 | controller | Collecting pip
2025-11-13 00:30:13.181016 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-13 00:30:13.258111 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.4 MB/s eta 0:00:00
2025-11-13 00:30:13.375062 | controller | Installing collected packages: pip
2025-11-13 00:30:13.375373 | controller |   Attempting uninstall: pip
2025-11-13 00:30:13.378677 | controller |     Found existing installation: pip 22.2.2
2025-11-13 00:30:13.599006 | controller |     Uninstalling pip-22.2.2:
2025-11-13 00:30:13.622829 | controller |       Successfully uninstalled pip-22.2.2
2025-11-13 00:30:15.300755 | controller | Successfully installed pip-25.3
2025-11-13 00:30:15.825349 | controller | ok: Runtime: 0:00:03.230575
2025-11-13 00:30:15.834252 | 
2025-11-13 00:30:15.834343 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-13 00:30:16.626101 | controller | changed
2025-11-13 00:30:16.638100 | 
2025-11-13 00:30:16.638257 | TASK [Install ansible into virtualenv]
2025-11-13 00:30:17.796301 | controller | Processing ./src/github.com/ansible/ansible
2025-11-13 00:30:17.804290 | controller |   Installing build dependencies: started
2025-11-13 00:30:19.574798 | controller |   Installing build dependencies: finished with status 'done'
2025-11-13 00:30:20.844379 | controller |   Getting requirements to build wheel: started
2025-11-13 00:30:20.844456 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-13 00:30:20.845878 | controller |   Preparing metadata (pyproject.toml): started
2025-11-13 00:30:21.584531 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-13 00:30:21.588310 | 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-13 00:30:21.591926 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-13 00:30:22.026643 | controller | ERROR
2025-11-13 00:30:22.027092 | controller | {
2025-11-13 00:30:22.027162 | controller |   "delta": "0:00:04.418926",
2025-11-13 00:30:22.027206 | controller |   "end": "2025-11-13 00:30:21.729364",
2025-11-13 00:30:22.027246 | controller |   "msg": "non-zero return code",
2025-11-13 00:30:22.027307 | controller |   "rc": 1,
2025-11-13 00:30:22.027347 | controller |   "start": "2025-11-13 00:30:17.310438"
2025-11-13 00:30:22.027384 | controller | }
failure
2025-11-13 00:30:22.030540 | 
2025-11-13 00:30:22.030723 | PLAY RECAP
2025-11-13 00:30:22.030869 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-13 00:30:22.030950 | 
2025-11-13 00:30:22.183230 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-13 00:30:22.184325 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-13 00:30:22.867949 | 
2025-11-13 00:30:22.868103 | PLAY [all]
2025-11-13 00:30:22.891737 | 
2025-11-13 00:30:22.891910 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-13 00:30:24.721274 | controller | changed: non-zero return code
2025-11-13 00:30:24.729394 | 
2025-11-13 00:30:24.729543 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-13 00:30:24.764804 | controller | skipping: Conditional result was False
2025-11-13 00:30:24.771471 | 
2025-11-13 00:30:24.771553 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-13 00:30:24.805936 | 
2025-11-13 00:30:24.806152 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-13 00:30:24.839143 | 
2025-11-13 00:30:24.839315 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-13 00:30:24.863750 | controller | skipping: Conditional result was False
2025-11-13 00:30:24.870364 | 
2025-11-13 00:30:24.870439 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-13 00:30:24.902309 | 
2025-11-13 00:30:24.902536 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-13 00:30:24.927229 | controller | skipping: Conditional result was False
2025-11-13 00:30:24.936185 | 
2025-11-13 00:30:24.936278 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-13 00:30:24.959980 | controller | skipping: Conditional result was False
2025-11-13 00:30:24.967265 | 
2025-11-13 00:30:24.967365 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-13 00:30:24.991520 | controller | skipping: Conditional result was False
2025-11-13 00:30:25.030529 | 
2025-11-13 00:30:25.030799 | PLAY RECAP
2025-11-13 00:30:25.030843 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-13 00:30:25.030863 | 
2025-11-13 00:30:25.156274 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-13 00:30:25.158920 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-13 00:30:25.775775 | 
2025-11-13 00:30:25.775914 | PLAY [all:!appliance*]
2025-11-13 00:30:25.823469 | 
2025-11-13 00:30:25.823822 | TASK [unregister the node]
2025-11-13 00:30:26.664044 | controller | skipping: Conditional result was False
2025-11-13 00:30:26.678383 | 
2025-11-13 00:30:26.678559 | TASK [include_role : fetch-output]
2025-11-13 00:30:26.733536 | controller | ok
2025-11-13 00:30:26.775771 | 
2025-11-13 00:30:26.775919 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-13 00:30:26.854759 | controller | skipping: Conditional result was False
2025-11-13 00:30:26.864559 | 
2025-11-13 00:30:26.864736 | TASK [fetch-output : Set log path for single node]
2025-11-13 00:30:26.914366 | controller | ok
2025-11-13 00:30:26.922395 | 
2025-11-13 00:30:26.922512 | LOOP [fetch-output : Ensure local output dirs]
2025-11-13 00:30:27.391206 | controller -> localhost | ok: "/var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/logs"
2025-11-13 00:30:27.660328 | controller -> localhost | changed: "/var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/artifacts"
2025-11-13 00:30:27.894487 | controller -> localhost | changed: "/var/lib/zuul/builds/dc51013698014064ad9653b7e8551f82/work/docs"
2025-11-13 00:30:27.909919 | 
2025-11-13 00:30:27.910136 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-13 00:30:30.224601 | controller | changed:
2025-11-13 00:30:30.225018 | controller | .d..t...... ./
2025-11-13 00:30:30.225081 | controller | cd+++++++++ controller/
2025-11-13 00:30:30.225154 | controller | changed: All items complete
2025-11-13 00:30:30.225200 | 
2025-11-13 00:30:32.271063 | controller | changed: .d..t...... ./
2025-11-13 00:30:34.370261 | controller | changed: .d..t...... ./
2025-11-13 00:30:34.400428 | 
2025-11-13 00:30:34.400649 | TASK [include_role : fetch-output-openshift]
2025-11-13 00:30:34.429830 | controller | skipping: Conditional result was False
2025-11-13 00:30:34.446542 | 
2025-11-13 00:30:34.446722 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-13 00:30:34.484514 | controller | skipping: Conditional result was False
2025-11-13 00:30:34.497227 | controller | skipping: Conditional result was False
2025-11-13 00:30:34.559888 | 
2025-11-13 00:30:34.560140 | PLAY [localhost]
2025-11-13 00:30:34.577559 | 
2025-11-13 00:30:34.577646 | TASK [Run Zuul manifest role]
2025-11-13 00:30:34.598126 | localhost | ok
2025-11-13 00:30:34.616020 | 
2025-11-13 00:30:34.616113 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-13 00:30:35.007585 | localhost | changed
2025-11-13 00:30:35.018927 | 
2025-11-13 00:30:35.019072 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-13 00:30:35.071438 | localhost | ok
2025-11-13 00:30:35.091627 | 
2025-11-13 00:30:35.091787 | TASK [Set zuul-log-path fact]
2025-11-13 00:30:35.152455 | localhost | ok
2025-11-13 00:30:35.167596 | 
2025-11-13 00:30:35.167689 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-13 00:30:35.196505 | localhost | ok
2025-11-13 00:30:35.204865 | 
2025-11-13 00:30:35.204928 | LOOP [Run upload-logs-swift role]
2025-11-13 00:30:35.229930 | localhost | Output suppressed because no_log was given
2025-11-13 00:30:35.259695 | 
2025-11-13 00:30:35.259839 | TASK [Set zuul-log-path fact]
2025-11-13 00:30:35.284679 | localhost | skipping: Conditional result was False
2025-11-13 00:30:35.290998 | 
2025-11-13 00:30:35.291068 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-13 00:30:35.654297 | localhost -> localhost | ok: Runtime: 0:00:00.009083
2025-11-13 00:30:35.667746 | 
2025-11-13 00:30:35.667970 | TASK [upload-logs-swift : Upload logs to swift]