2025-11-02 00:12:12.503926 | Job console starting...
2025-11-02 00:12:12.513161 | Updating repositories
2025-11-02 00:12:12.646856 | Preparing job workspace
2025-11-02 00:12:16.465112 | Running Ansible setup...
2025-11-02 00:12:22.894160 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-02 00:12:23.583634 | 
2025-11-02 00:12:23.583812 | PLAY [localhost]
2025-11-02 00:12:23.593501 | 
2025-11-02 00:12:23.593583 | TASK [Gathering Facts]
2025-11-02 00:12:24.581861 | localhost | ok
2025-11-02 00:12:24.601571 | 
2025-11-02 00:12:24.601818 | TASK [Setup log path fact]
2025-11-02 00:12:24.620330 | localhost | ok
2025-11-02 00:12:24.635576 | 
2025-11-02 00:12:24.635711 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-02 00:12:24.665516 | localhost | ok
2025-11-02 00:12:24.673897 | 
2025-11-02 00:12:24.673985 | TASK [emit-job-header : Print job information]
2025-11-02 00:12:24.702171 | # Job Information
2025-11-02 00:12:24.702417 | Ansible Version: 2.15.12
2025-11-02 00:12:24.702465 | Job: ansible-test-sanity-docker-milestone
2025-11-02 00:12:24.702493 | Pipeline: periodic
2025-11-02 00:12:24.702515 | Executor: ze04.softwarefactory-project.io
2025-11-02 00:12:24.702534 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-02 00:12:24.702554 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/f00/ansible/f003abe06e62479fb1f3aa58da5cd015/
2025-11-02 00:12:24.702573 | Event ID: ab268dade05340f0bccc28ef5656c369
2025-11-02 00:12:24.706891 | 
2025-11-02 00:12:24.706970 | LOOP [emit-job-header : Print node information]
2025-11-02 00:12:24.860837 | localhost | ok:
2025-11-02 00:12:24.861018 | localhost | # Node Information
2025-11-02 00:12:24.861045 | localhost | Inventory Hostname: controller
2025-11-02 00:12:24.861064 | localhost | Hostname: ip-172-16-6-18
2025-11-02 00:12:24.861083 | localhost | Username: zuul-worker
2025-11-02 00:12:24.861103 | localhost | Distro: Fedora 37
2025-11-02 00:12:24.861122 | localhost | Provider: ansible-us-east-2
2025-11-02 00:12:24.861140 | localhost | Region: us-east-2
2025-11-02 00:12:24.861157 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-02 00:12:24.861174 | localhost | Product Name: t3.small
2025-11-02 00:12:24.861191 | localhost | Interface IP: 18.116.114.213
2025-11-02 00:12:24.872825 | 
2025-11-02 00:12:24.872949 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-02 00:12:25.315130 | localhost -> localhost | changed
2025-11-02 00:12:25.322459 | 
2025-11-02 00:12:25.322538 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-02 00:12:26.254374 | localhost -> localhost | changed
2025-11-02 00:12:26.277289 | 
2025-11-02 00:12:26.277373 | PLAY [all:!appliance*]
2025-11-02 00:12:26.294674 | 
2025-11-02 00:12:26.294808 | TASK [include_role : start-zuul-console]
2025-11-02 00:12:26.315018 | controller | ok
2025-11-02 00:12:26.330953 | 
2025-11-02 00:12:26.331071 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-02 00:12:27.040497 | controller | ok
2025-11-02 00:12:27.058232 | 
2025-11-02 00:12:27.058334 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-02 00:12:28.914358 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-02 00:12:28.924726 | 
2025-11-02 00:12:28.924901 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-02 00:12:29.080730 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.087605 | 
2025-11-02 00:12:29.087705 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-02 00:12:29.111860 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.118364 | 
2025-11-02 00:12:29.118438 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-02 00:12:29.142621 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.149119 | 
2025-11-02 00:12:29.149188 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-02 00:12:29.172893 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.179760 | 
2025-11-02 00:12:29.179847 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-02 00:12:29.203592 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.209967 | 
2025-11-02 00:12:29.210065 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-02 00:12:29.233735 | controller | skipping: Conditional result was False
2025-11-02 00:12:29.246608 | 
2025-11-02 00:12:29.246731 | TASK [Disable Fedora Modular]
2025-11-02 00:12:30.031113 | controller | changed
2025-11-02 00:12:30.050234 | 
2025-11-02 00:12:30.050390 | TASK [Enable EPEL]
2025-11-02 00:12:30.077382 | controller | skipping: Conditional result was False
2025-11-02 00:12:30.086655 | 
2025-11-02 00:12:30.086828 | TASK [Register the RHEL node]
2025-11-02 00:12:30.287981 | 
2025-11-02 00:12:30.288161 | TASK [Show the subscription-manager status]
2025-11-02 00:12:30.526243 | controller | skipping: Conditional result was False
2025-11-02 00:12:30.537071 | 
2025-11-02 00:12:30.537185 | TASK [Enable EPEL on RHEL]
2025-11-02 00:12:30.725192 | controller | skipping: Conditional result was False
2025-11-02 00:12:30.742562 | 
2025-11-02 00:12:30.742750 | TASK [Install git and tox]
2025-11-02 00:14:00.950352 | controller | changed
2025-11-02 00:14:00.957214 | 
2025-11-02 00:14:00.957356 | TASK [include_role : prepare-workspace]
2025-11-02 00:14:00.989205 | controller | ok
2025-11-02 00:14:01.011587 | 
2025-11-02 00:14:01.011750 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-02 00:14:02.251845 | controller | ok
2025-11-02 00:14:02.259327 | 
2025-11-02 00:14:02.259425 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-02 00:14:15.986917 | controller | Output suppressed because no_log was given
2025-11-02 00:14:16.011075 | 
2025-11-02 00:14:16.011303 | TASK [include_role : prepare-workspace-openshift]
2025-11-02 00:14:16.040317 | controller | skipping: Conditional result was False
2025-11-02 00:14:16.078062 | 
2025-11-02 00:14:16.078222 | PLAY [all:!appliance]
2025-11-02 00:14:16.099990 | 
2025-11-02 00:14:16.100195 | TASK [Run add-build-sshkey role (RSA)]
2025-11-02 00:14:16.140182 | controller | ok
2025-11-02 00:14:16.160403 | 
2025-11-02 00:14:16.160550 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-02 00:14:16.408996 | controller -> localhost | ok
2025-11-02 00:14:16.418861 | 
2025-11-02 00:14:16.419016 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-02 00:14:16.443152 | controller | ok
2025-11-02 00:14:16.462828 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-02 00:14:16.508941 | 
2025-11-02 00:14:16.509159 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-02 00:14:17.073393 | controller -> localhost | Generating public/private rsa key pair.
2025-11-02 00:14:17.073904 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_rsa.
2025-11-02 00:14:17.073986 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_rsa.pub.
2025-11-02 00:14:17.074044 | controller -> localhost | The key fingerprint is:
2025-11-02 00:14:17.074099 | controller -> localhost | SHA256:yNYzSu5zgTI6t3fHLM4PP9Hy5Z+DxRCx6EY5pprogqo zuul-build-sshkey
2025-11-02 00:14:17.074152 | controller -> localhost | The key's randomart image is:
2025-11-02 00:14:17.074206 | controller -> localhost | +---[RSA 2048]----+
2025-11-02 00:14:17.074256 | controller -> localhost | |             ..  |
2025-11-02 00:14:17.074307 | controller -> localhost | |            o..  |
2025-11-02 00:14:17.074356 | controller -> localhost | |           * ..  |
2025-11-02 00:14:17.074405 | controller -> localhost | |     . o  = ..   |
2025-11-02 00:14:17.074454 | controller -> localhost | |      =.S. +  o  |
2025-11-02 00:14:17.074526 | controller -> localhost | |    o+o.+o+ . .o |
2025-11-02 00:14:17.074587 | controller -> localhost | |  .. +oo.+ + oo  |
2025-11-02 00:14:17.074640 | controller -> localhost | | .o.o.o.+o= .....|
2025-11-02 00:14:17.075164 | controller -> localhost | |E  oo+.=o+o.   oo|
2025-11-02 00:14:17.075256 | controller -> localhost | +----[SHA256]-----+
2025-11-02 00:14:17.075388 | controller -> localhost | ok: Runtime: 0:00:00.124447
2025-11-02 00:14:17.090887 | 
2025-11-02 00:14:17.091141 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-02 00:14:17.141816 | controller | ok
2025-11-02 00:14:17.165586 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-02 00:14:17.178986 | 
2025-11-02 00:14:17.179162 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-02 00:14:17.215191 | controller | skipping: Conditional result was False
2025-11-02 00:14:17.224348 | 
2025-11-02 00:14:17.224438 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-02 00:14:17.879398 | controller | changed
2025-11-02 00:14:17.897655 | 
2025-11-02 00:14:17.897849 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-02 00:14:18.267648 | controller | ok
2025-11-02 00:14:18.281263 | 
2025-11-02 00:14:18.281413 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-02 00:14:19.633128 | controller | changed
2025-11-02 00:14:19.645344 | 
2025-11-02 00:14:19.645494 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-02 00:14:20.998752 | controller | changed
2025-11-02 00:14:21.005829 | 
2025-11-02 00:14:21.005917 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-02 00:14:21.032395 | controller | skipping: Conditional result was False
2025-11-02 00:14:21.043174 | 
2025-11-02 00:14:21.043276 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-02 00:14:21.421836 | controller -> localhost | changed
2025-11-02 00:14:21.444866 | 
2025-11-02 00:14:21.445057 | TASK [add-build-sshkey : Add back temp key]
2025-11-02 00:14:21.787895 | controller -> localhost | Identity added: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_rsa (zuul-build-sshkey)
2025-11-02 00:14:21.788244 | controller -> localhost | ok: Runtime: 0:00:00.009464
2025-11-02 00:14:21.798027 | 
2025-11-02 00:14:21.798133 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-02 00:14:22.292545 | controller | ok
2025-11-02 00:14:22.306145 | 
2025-11-02 00:14:22.306297 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-02 00:14:22.355082 | controller | skipping: Conditional result was False
2025-11-02 00:14:22.380070 | 
2025-11-02 00:14:22.380283 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-02 00:14:22.416833 | controller | ok
2025-11-02 00:14:22.440588 | 
2025-11-02 00:14:22.440725 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-02 00:14:22.805824 | controller -> localhost | ok
2025-11-02 00:14:22.821938 | 
2025-11-02 00:14:22.822110 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-02 00:14:22.855297 | controller | ok
2025-11-02 00:14:22.878898 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-02 00:14:22.893615 | 
2025-11-02 00:14:22.893870 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-02 00:14:23.204952 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-02 00:14:23.205171 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_ecdsa.
2025-11-02 00:14:23.205201 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_ecdsa.pub.
2025-11-02 00:14:23.205232 | controller -> localhost | The key fingerprint is:
2025-11-02 00:14:23.205253 | controller -> localhost | SHA256:9fOXZu5uHLmL9p6m7z2Tx/cW2FbaQY9zs4f1dYlY6rk zuul-build-sshkey
2025-11-02 00:14:23.205276 | controller -> localhost | The key's randomart image is:
2025-11-02 00:14:23.205296 | controller -> localhost | +---[ECDSA 521]---+
2025-11-02 00:14:23.205316 | controller -> localhost | |                 |
2025-11-02 00:14:23.205334 | controller -> localhost | |             . . |
2025-11-02 00:14:23.205352 | controller -> localhost | |          . + o.o|
2025-11-02 00:14:23.205370 | controller -> localhost | |         . + .o+B|
2025-11-02 00:14:23.205387 | controller -> localhost | |        S . + oBX|
2025-11-02 00:14:23.205406 | controller -> localhost | |           o +oB=|
2025-11-02 00:14:23.205424 | controller -> localhost | |            . +=B|
2025-11-02 00:14:23.205441 | controller -> localhost | |           E .=XB|
2025-11-02 00:14:23.205460 | controller -> localhost | |            .o@%X|
2025-11-02 00:14:23.205478 | controller -> localhost | +----[SHA256]-----+
2025-11-02 00:14:23.205534 | controller -> localhost | ok: Runtime: 0:00:00.010458
2025-11-02 00:14:23.212492 | 
2025-11-02 00:14:23.212568 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-02 00:14:23.245445 | controller | ok
2025-11-02 00:14:23.253285 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-02 00:14:23.262498 | 
2025-11-02 00:14:23.262584 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-02 00:14:23.287937 | controller | skipping: Conditional result was False
2025-11-02 00:14:23.295199 | 
2025-11-02 00:14:23.295285 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-02 00:14:23.758289 | controller | changed
2025-11-02 00:14:23.766307 | 
2025-11-02 00:14:23.766394 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-02 00:14:24.122696 | controller | ok
2025-11-02 00:14:24.132753 | 
2025-11-02 00:14:24.132881 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-02 00:14:25.500880 | controller | changed
2025-11-02 00:14:25.508643 | 
2025-11-02 00:14:25.508756 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-02 00:14:26.837647 | controller | changed
2025-11-02 00:14:26.846658 | 
2025-11-02 00:14:26.846864 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-02 00:14:26.876127 | controller | skipping: Conditional result was False
2025-11-02 00:14:26.885655 | 
2025-11-02 00:14:26.885846 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-02 00:14:27.131210 | controller -> localhost | changed
2025-11-02 00:14:27.147019 | 
2025-11-02 00:14:27.147151 | TASK [add-build-sshkey : Add back temp key]
2025-11-02 00:14:27.494982 | controller -> localhost | Identity added: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/f003abe06e62479fb1f3aa58da5cd015_id_ecdsa (zuul-build-sshkey)
2025-11-02 00:14:27.495315 | controller -> localhost | ok: Runtime: 0:00:00.011695
2025-11-02 00:14:27.502586 | 
2025-11-02 00:14:27.502714 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-02 00:14:27.857887 | controller | ok
2025-11-02 00:14:27.873969 | 
2025-11-02 00:14:27.874377 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-02 00:14:27.927448 | controller | skipping: Conditional result was False
2025-11-02 00:14:27.943511 | 
2025-11-02 00:14:27.943899 | TASK [include_role : remove-zuul-sshkey]
2025-11-02 00:14:27.971989 | controller | skipping: Conditional result was False
2025-11-02 00:14:27.986459 | 
2025-11-02 00:14:27.986760 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-02 00:14:28.324752 | controller | ok: "logs"
2025-11-02 00:14:28.325049 | controller | ok: All items complete
2025-11-02 00:14:28.325076 | 
2025-11-02 00:14:28.620910 | controller | ok: "artifacts"
2025-11-02 00:14:28.911557 | controller | ok: "docs"
2025-11-02 00:14:28.925086 | 
2025-11-02 00:14:28.925247 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-02 00:14:29.271390 | controller | changed: "logs"
2025-11-02 00:14:29.612528 | controller | changed: "artifacts"
2025-11-02 00:14:29.847640 | controller | changed: "docs"
2025-11-02 00:14:29.903634 | 
2025-11-02 00:14:29.903793 | PLAY RECAP
2025-11-02 00:14:29.903842 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-02 00:14:29.903869 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-02 00:14:29.903889 | 
2025-11-02 00:14:30.059005 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-02 00:14:30.059993 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-02 00:14:30.738711 | 
2025-11-02 00:14:30.738846 | PLAY [all]
2025-11-02 00:14:30.761179 | 
2025-11-02 00:14:30.761291 | TASK [Install binary dependencies]
2025-11-02 00:14:30.817944 | controller | ok
2025-11-02 00:14:30.838507 | 
2025-11-02 00:14:30.838599 | TASK [bindep : Include find tasks]
2025-11-02 00:14:30.878589 | controller | ok
2025-11-02 00:14:30.886449 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-02 00:14:30.892706 | 
2025-11-02 00:14:30.892771 | TASK [bindep : Look for bindep.txt]
2025-11-02 00:14:31.481048 | controller | ok
2025-11-02 00:14:31.494934 | 
2025-11-02 00:14:31.495103 | TASK [bindep : Define bindep_file fact]
2025-11-02 00:14:31.523308 | controller | skipping: Conditional result was False
2025-11-02 00:14:31.539264 | 
2025-11-02 00:14:31.539489 | TASK [bindep : Look for other-requirements.txt]
2025-11-02 00:14:31.865939 | controller | ok
2025-11-02 00:14:31.877986 | 
2025-11-02 00:14:31.878131 | TASK [bindep : Define bindep_file fact]
2025-11-02 00:14:31.917326 | controller | skipping: Conditional result was False
2025-11-02 00:14:31.931028 | 
2025-11-02 00:14:31.931160 | TASK [bindep : Look for bindep fallback file]
2025-11-02 00:14:31.968944 | controller | skipping: Conditional result was False
2025-11-02 00:14:31.978925 | 
2025-11-02 00:14:31.979058 | TASK [bindep : Define bindep_file fact]
2025-11-02 00:14:32.007807 | controller | skipping: Conditional result was False
2025-11-02 00:14:32.017565 | 
2025-11-02 00:14:32.017754 | TASK [bindep : Include bindep tasks]
2025-11-02 00:14:32.044470 | controller | skipping: Conditional result was False
2025-11-02 00:14:32.058070 | 
2025-11-02 00:14:32.058229 | TASK [bindep : Include install tasks]
2025-11-02 00:14:32.105130 | controller | skipping: Conditional result was False
2025-11-02 00:14:32.123028 | 
2025-11-02 00:14:32.123232 | LOOP [bindep : Include package tasks]
2025-11-02 00:14:32.225523 | 
2025-11-02 00:14:32.225907 | TASK [Run test-setup role]
2025-11-02 00:14:32.250343 | controller | ok
2025-11-02 00:14:32.269637 | 
2025-11-02 00:14:32.269734 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-02 00:14:32.589153 | controller | ok
2025-11-02 00:14:32.597279 | 
2025-11-02 00:14:32.597378 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-02 00:14:32.749981 | controller | skipping: Conditional result was False
2025-11-02 00:14:32.803033 | 
2025-11-02 00:14:32.803201 | PLAY RECAP
2025-11-02 00:14:32.803263 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-02 00:14:32.803292 | 
2025-11-02 00:14:32.944000 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-02 00:14:32.945269 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-02 00:14:33.625717 | 
2025-11-02 00:14:33.626126 | PLAY [controller]
2025-11-02 00:14:33.652582 | 
2025-11-02 00:14:33.652834 | TASK [Create the /root directory]
2025-11-02 00:14:34.466321 | controller | ok
2025-11-02 00:14:34.478847 | 
2025-11-02 00:14:34.479014 | TASK [Install glibc-langpack-en]
2025-11-02 00:14:42.709500 | controller | ok: Nothing to do
2025-11-02 00:14:42.718371 | 
2025-11-02 00:14:42.718503 | TASK [Ensure controller directory exists]
2025-11-02 00:14:43.145008 | controller | changed
2025-11-02 00:14:43.157444 | 
2025-11-02 00:14:43.157600 | TASK [Install container runtime]
2025-11-02 00:14:43.209872 | controller | ok
2025-11-02 00:14:43.271848 | 
2025-11-02 00:14:43.272009 | LOOP [ensure-podman : Find distribution installation]
2025-11-02 00:14:43.325162 | controller | ok: "/var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-02 00:14:43.338045 | controller | included: /var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-02 00:14:43.345139 | 
2025-11-02 00:14:43.345219 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-02 00:16:03.464149 | controller | changed
2025-11-02 00:16:03.481465 | 
2025-11-02 00:16:03.481631 | TASK [ensure-podman : Fetch podman version]
2025-11-02 00:16:04.339861 | controller | Client:       Podman Engine
2025-11-02 00:16:04.367187 | controller | Version:      4.6.2
2025-11-02 00:16:04.367236 | controller | API Version:  4.6.2
2025-11-02 00:16:04.367248 | controller | Go Version:   go1.19.12
2025-11-02 00:16:04.367271 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-02 00:16:04.367281 | controller | OS/Arch:      linux/amd64
2025-11-02 00:16:04.643739 | controller | ok: Runtime: 0:00:00.245447
2025-11-02 00:16:04.651090 | 
2025-11-02 00:16:04.651203 | TASK [ensure-podman : Print podman version installed]
2025-11-02 00:16:04.694649 | Podman version: Client:       Podman Engine
2025-11-02 00:16:04.694856 | Version:      4.6.2
2025-11-02 00:16:04.694887 | API Version:  4.6.2
2025-11-02 00:16:04.694908 | Go Version:   go1.19.12
2025-11-02 00:16:04.694927 | Built:        Mon Aug 28 19:38:31 2023
2025-11-02 00:16:04.694946 | OS/Arch:      linux/amd64
2025-11-02 00:16:04.704704 | 
2025-11-02 00:16:04.704918 | TASK [ensure-podman : Validate podman engine]
2025-11-02 00:16:04.845424 | controller | skipping: Conditional result was False
2025-11-02 00:16:04.857194 | 
2025-11-02 00:16:04.857346 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-02 00:16:04.874515 | controller | skipping: Conditional result was False
2025-11-02 00:16:04.888930 | 
2025-11-02 00:16:04.889057 | TASK [Ensure python3.8 is present]
2025-11-02 00:16:04.915942 | controller | skipping: Conditional result was False
2025-11-02 00:16:04.922880 | 
2025-11-02 00:16:04.922953 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-02 00:16:04.944712 | controller | ok
2025-11-02 00:16:04.963871 | 
2025-11-02 00:16:04.963967 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-02 00:16:08.680792 | controller | ok: Nothing to do
2025-11-02 00:16:08.696347 | 
2025-11-02 00:16:08.696914 | TASK [our-ensure-python : Also install python3-devel]
2025-11-02 00:16:22.606267 | controller | changed
2025-11-02 00:16:22.630488 | 
2025-11-02 00:16:22.630606 | TASK [Run ensure-virtualenv role]
2025-11-02 00:16:22.658577 | controller | ok
2025-11-02 00:16:22.680836 | 
2025-11-02 00:16:22.680924 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-02 00:16:23.091222 | controller | /usr/bin/virtualenv
2025-11-02 00:16:23.327768 | controller | ok: Runtime: 0:00:00.005235
2025-11-02 00:16:23.342801 | 
2025-11-02 00:16:23.342949 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-02 00:16:23.388508 | controller | skipping: Conditional result was False
2025-11-02 00:16:23.389136 | controller | ok: All items complete
2025-11-02 00:16:23.389204 | 
2025-11-02 00:16:23.415562 | 
2025-11-02 00:16:23.415818 | TASK [Find the full path of the Python interpreter]
2025-11-02 00:16:23.950221 | controller | /usr/bin/python3
2025-11-02 00:16:24.120143 | controller | ok
2025-11-02 00:16:24.128839 | 
2025-11-02 00:16:24.128965 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-02 00:16:25.582700 | controller | created virtual environment CPython3.11.0.final.0-64 in 748ms
2025-11-02 00:16:25.625380 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-02 00:16:25.625436 | 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-11-02 00:16:25.625454 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-02 00:16:25.625478 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-02 00:16:25.792449 | controller | changed
2025-11-02 00:16:25.805389 | 
2025-11-02 00:16:25.805548 | TASK [Set selinux package]
2025-11-02 00:16:25.847280 | controller | ok
2025-11-02 00:16:25.859454 | 
2025-11-02 00:16:25.859636 | TASK [Set selinux package (Fedora)]
2025-11-02 00:16:25.895105 | controller | ok
2025-11-02 00:16:25.903102 | 
2025-11-02 00:16:25.903217 | TASK [Install selinux into virtualenv]
2025-11-02 00:16:28.574254 | controller | Collecting selinux-please-lie-to-me
2025-11-02 00:16:28.661082 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-02 00:16:29.191638 | controller | Collecting setuptools<50.0.0
2025-11-02 00:16:29.204674 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-02 00:16:29.339816 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.3 MB/s eta 0:00:00
2025-11-02 00:16:29.492671 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-02 00:16:29.492975 | controller |   Attempting uninstall: setuptools
2025-11-02 00:16:29.497850 | controller |     Found existing installation: setuptools 62.6.0
2025-11-02 00:16:29.609079 | controller |     Uninstalling setuptools-62.6.0:
2025-11-02 00:16:29.624283 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-02 00:16:30.360568 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-02 00:16:30.566759 | controller |
2025-11-02 00:16:30.784210 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-02 00:16:30.784260 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-02 00:16:31.101955 | controller | ok: Runtime: 0:00:04.392621
2025-11-02 00:16:31.109950 | 
2025-11-02 00:16:31.110070 | TASK [Install pytest-forked into virtualenv]
2025-11-02 00:16:32.347138 | controller | Collecting pytest-forked
2025-11-02 00:16:32.438794 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-02 00:16:32.499197 | controller | Collecting py
2025-11-02 00:16:32.513692 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-02 00:16:32.550835 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-11-02 00:16:32.728475 | controller | Collecting pytest>=3.10
2025-11-02 00:16:32.742876 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-11-02 00:16:32.804899 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00
2025-11-02 00:16:32.861922 | controller | Collecting iniconfig>=1
2025-11-02 00:16:32.876356 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-02 00:16:32.943793 | controller | Collecting packaging>=20
2025-11-02 00:16:32.957963 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-02 00:16:32.973534 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.8 MB/s eta 0:00:00
2025-11-02 00:16:33.034590 | controller | Collecting pluggy<2,>=1.5
2025-11-02 00:16:33.048805 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-02 00:16:33.123899 | controller | Collecting pygments>=2.7.2
2025-11-02 00:16:33.138127 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-02 00:16:33.270856 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.4 MB/s eta 0:00:00
2025-11-02 00:16:33.403158 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-02 00:16:35.670723 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-11-02 00:16:35.686969 | controller |
2025-11-02 00:16:35.875309 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-02 00:16:35.875360 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-02 00:16:36.292282 | controller | ok: Runtime: 0:00:04.263971
2025-11-02 00:16:36.305917 | 
2025-11-02 00:16:36.306084 | TASK [Update pip]
2025-11-02 00:16:37.454609 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-02 00:16:37.743466 | controller | Collecting pip
2025-11-02 00:16:37.844184 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-02 00:16:38.005236 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.6 MB/s eta 0:00:00
2025-11-02 00:16:38.181506 | controller | Installing collected packages: pip
2025-11-02 00:16:38.181804 | controller |   Attempting uninstall: pip
2025-11-02 00:16:38.186342 | controller |     Found existing installation: pip 22.2.2
2025-11-02 00:16:38.444758 | controller |     Uninstalling pip-22.2.2:
2025-11-02 00:16:38.474792 | controller |       Successfully uninstalled pip-22.2.2
2025-11-02 00:16:40.209153 | controller | Successfully installed pip-25.3
2025-11-02 00:16:40.480606 | controller | ok: Runtime: 0:00:03.554622
2025-11-02 00:16:40.493960 | 
2025-11-02 00:16:40.494103 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-02 00:16:41.057534 | controller | changed
2025-11-02 00:16:41.066173 | 
2025-11-02 00:16:41.066492 | TASK [Install ansible into virtualenv]
2025-11-02 00:16:42.100752 | controller | Processing ./src/github.com/ansible/ansible
2025-11-02 00:16:42.107338 | controller |   Installing build dependencies: started
2025-11-02 00:16:44.125211 | controller |   Installing build dependencies: finished with status 'done'
2025-11-02 00:16:44.125879 | controller |   Getting requirements to build wheel: started
2025-11-02 00:16:45.672358 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-02 00:16:46.595456 | controller |   Preparing metadata (pyproject.toml): started
2025-11-02 00:16:46.595504 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-02 00:16:46.600074 | 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-02 00:16:46.604855 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-02 00:16:47.228894 | controller | ERROR
2025-11-02 00:16:47.229178 | controller | {
2025-11-02 00:16:47.229217 | controller |   "delta": "0:00:05.223556",
2025-11-02 00:16:47.229238 | controller |   "end": "2025-11-02 00:16:46.752465",
2025-11-02 00:16:47.229256 | controller |   "msg": "non-zero return code",
2025-11-02 00:16:47.229285 | controller |   "rc": 1,
2025-11-02 00:16:47.229303 | controller |   "start": "2025-11-02 00:16:41.528909"
2025-11-02 00:16:47.229319 | controller | }
failure
2025-11-02 00:16:47.232173 | 
2025-11-02 00:16:47.232246 | PLAY RECAP
2025-11-02 00:16:47.232294 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-02 00:16:47.232314 | 
2025-11-02 00:16:47.454013 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-02 00:16:47.455211 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-02 00:16:48.120261 | 
2025-11-02 00:16:48.120473 | PLAY [all]
2025-11-02 00:16:48.143674 | 
2025-11-02 00:16:48.143880 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-02 00:16:48.977293 | controller | changed: non-zero return code
2025-11-02 00:16:48.993130 | 
2025-11-02 00:16:48.993363 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-02 00:16:49.023428 | controller | skipping: Conditional result was False
2025-11-02 00:16:49.032799 | 
2025-11-02 00:16:49.032895 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-02 00:16:49.067120 | 
2025-11-02 00:16:49.067322 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-02 00:16:49.100202 | 
2025-11-02 00:16:49.100411 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-02 00:16:49.126440 | controller | skipping: Conditional result was False
2025-11-02 00:16:49.137378 | 
2025-11-02 00:16:49.137978 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-02 00:16:49.173941 | 
2025-11-02 00:16:49.174181 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-02 00:16:49.199980 | controller | skipping: Conditional result was False
2025-11-02 00:16:49.207142 | 
2025-11-02 00:16:49.207222 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-02 00:16:49.232617 | controller | skipping: Conditional result was False
2025-11-02 00:16:49.241387 | 
2025-11-02 00:16:49.241506 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-02 00:16:49.266034 | controller | skipping: Conditional result was False
2025-11-02 00:16:49.296064 | 
2025-11-02 00:16:49.296186 | PLAY RECAP
2025-11-02 00:16:49.296230 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-02 00:16:49.296253 | 
2025-11-02 00:16:49.437152 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-02 00:16:49.439239 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-02 00:16:50.079514 | 
2025-11-02 00:16:50.079654 | PLAY [all:!appliance*]
2025-11-02 00:16:50.110144 | 
2025-11-02 00:16:50.110298 | TASK [unregister the node]
2025-11-02 00:16:50.261872 | controller | skipping: Conditional result was False
2025-11-02 00:16:50.268432 | 
2025-11-02 00:16:50.268549 | TASK [include_role : fetch-output]
2025-11-02 00:16:50.299818 | controller | ok
2025-11-02 00:16:50.351598 | 
2025-11-02 00:16:50.351797 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-02 00:16:50.420908 | controller | skipping: Conditional result was False
2025-11-02 00:16:50.428193 | 
2025-11-02 00:16:50.428356 | TASK [fetch-output : Set log path for single node]
2025-11-02 00:16:50.476846 | controller | ok
2025-11-02 00:16:50.491534 | 
2025-11-02 00:16:50.492369 | LOOP [fetch-output : Ensure local output dirs]
2025-11-02 00:16:51.007560 | controller -> localhost | ok: "/var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/logs"
2025-11-02 00:16:51.340914 | controller -> localhost | changed: "/var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/artifacts"
2025-11-02 00:16:51.583441 | controller -> localhost | changed: "/var/lib/zuul/builds/f003abe06e62479fb1f3aa58da5cd015/work/docs"
2025-11-02 00:16:51.606187 | 
2025-11-02 00:16:51.606336 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-02 00:16:52.844248 | controller | changed:
2025-11-02 00:16:52.844469 | controller | .d..t...... ./
2025-11-02 00:16:52.844498 | controller | cd+++++++++ controller/
2025-11-02 00:16:52.844531 | controller | changed: All items complete
2025-11-02 00:16:52.844552 | 
2025-11-02 00:16:53.893017 | controller | changed: .d..t...... ./
2025-11-02 00:16:54.977076 | controller | changed: .d..t...... ./
2025-11-02 00:16:54.997400 | 
2025-11-02 00:16:54.997516 | TASK [include_role : fetch-output-openshift]
2025-11-02 00:16:55.012275 | controller | skipping: Conditional result was False
2025-11-02 00:16:55.019470 | 
2025-11-02 00:16:55.019547 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-02 00:16:55.052457 | controller | skipping: Conditional result was False
2025-11-02 00:16:55.061710 | controller | skipping: Conditional result was False
2025-11-02 00:16:55.100691 | 
2025-11-02 00:16:55.100987 | PLAY [localhost]
2025-11-02 00:16:55.115077 | 
2025-11-02 00:16:55.115245 | TASK [Run Zuul manifest role]
2025-11-02 00:16:55.137378 | localhost | ok
2025-11-02 00:16:55.157623 | 
2025-11-02 00:16:55.157781 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-02 00:16:55.592861 | localhost | changed
2025-11-02 00:16:55.606175 | 
2025-11-02 00:16:55.606382 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-02 00:16:55.656005 | localhost | ok
2025-11-02 00:16:55.679001 | 
2025-11-02 00:16:55.679221 | TASK [Set zuul-log-path fact]
2025-11-02 00:16:55.707431 | localhost | ok
2025-11-02 00:16:55.735552 | 
2025-11-02 00:16:55.735768 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-02 00:16:55.770341 | localhost | ok
2025-11-02 00:16:55.787256 | 
2025-11-02 00:16:55.787442 | LOOP [Run upload-logs-swift role]
2025-11-02 00:16:55.814647 | localhost | Output suppressed because no_log was given
2025-11-02 00:16:55.859391 | 
2025-11-02 00:16:55.859562 | TASK [Set zuul-log-path fact]
2025-11-02 00:16:55.886847 | localhost | skipping: Conditional result was False
2025-11-02 00:16:55.895266 | 
2025-11-02 00:16:55.895437 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-02 00:16:56.381799 | localhost -> localhost | ok: Runtime: 0:00:00.006371
2025-11-02 00:16:56.394300 | 
2025-11-02 00:16:56.394443 | TASK [upload-logs-swift : Upload logs to swift]