2025-10-04 00:06:45.016761 | Job console starting...
2025-10-04 00:06:45.027581 | Updating repositories
2025-10-04 00:06:48.313930 | Preparing job workspace
2025-10-04 00:07:03.059506 | Running Ansible setup...
2025-10-04 00:07:09.256063 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-04 00:07:09.918511 | 
2025-10-04 00:07:09.918636 | PLAY [localhost]
2025-10-04 00:07:09.927528 | 
2025-10-04 00:07:09.927637 | TASK [Gathering Facts]
2025-10-04 00:07:11.030055 | localhost | ok
2025-10-04 00:07:11.049231 | 
2025-10-04 00:07:11.049354 | TASK [Setup log path fact]
2025-10-04 00:07:11.067865 | localhost | ok
2025-10-04 00:07:11.080333 | 
2025-10-04 00:07:11.080414 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-04 00:07:11.108887 | localhost | ok
2025-10-04 00:07:11.117425 | 
2025-10-04 00:07:11.117555 | TASK [emit-job-header : Print job information]
2025-10-04 00:07:11.146556 | # Job Information
2025-10-04 00:07:11.146726 | Ansible Version: 2.15.12
2025-10-04 00:07:11.146759 | Job: ansible-test-sanity-docker-devel
2025-10-04 00:07:11.146780 | Pipeline: periodic
2025-10-04 00:07:11.146798 | Executor: ze04.softwarefactory-project.io
2025-10-04 00:07:11.146816 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-04 00:07:11.146839 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/395/ansible/395cb5ca03af4b1f9277eae39d6a0031/
2025-10-04 00:07:11.146859 | Event ID: 94a13ac06c46427a92df5bbab63fdd0f
2025-10-04 00:07:11.151524 | 
2025-10-04 00:07:11.151794 | LOOP [emit-job-header : Print node information]
2025-10-04 00:07:11.280167 | localhost | ok:
2025-10-04 00:07:11.280601 | localhost | # Node Information
2025-10-04 00:07:11.280648 | localhost | Inventory Hostname: controller
2025-10-04 00:07:11.281001 | localhost | Hostname: ip-172-16-201-33
2025-10-04 00:07:11.281045 | localhost | Username: zuul-worker
2025-10-04 00:07:11.281077 | localhost | Distro: Fedora 37
2025-10-04 00:07:11.281106 | localhost | Provider: ansible-us-east-2
2025-10-04 00:07:11.281133 | localhost | Region: us-east-2
2025-10-04 00:07:11.281159 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-04 00:07:11.281185 | localhost | Product Name: t3.small
2025-10-04 00:07:11.281210 | localhost | Interface IP: 18.118.218.185
2025-10-04 00:07:11.302362 | 
2025-10-04 00:07:11.302487 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-04 00:07:11.700334 | localhost -> localhost | changed
2025-10-04 00:07:11.712969 | 
2025-10-04 00:07:11.713111 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-04 00:07:13.085426 | localhost -> localhost | changed
2025-10-04 00:07:13.105144 | 
2025-10-04 00:07:13.105204 | PLAY [all:!appliance*]
2025-10-04 00:07:13.120268 | 
2025-10-04 00:07:13.120347 | TASK [include_role : start-zuul-console]
2025-10-04 00:07:13.150626 | controller | ok
2025-10-04 00:07:13.164181 | 
2025-10-04 00:07:13.164246 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-04 00:07:13.867191 | controller | ok
2025-10-04 00:07:13.888751 | 
2025-10-04 00:07:13.888839 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-04 00:07:15.705870 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-04 00:07:15.717420 | 
2025-10-04 00:07:15.717501 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-04 00:07:15.867470 | controller | skipping: Conditional result was False
2025-10-04 00:07:15.874987 | 
2025-10-04 00:07:15.875059 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-04 00:07:15.909516 | controller | skipping: Conditional result was False
2025-10-04 00:07:15.923081 | 
2025-10-04 00:07:15.923213 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-04 00:07:15.960333 | controller | skipping: Conditional result was False
2025-10-04 00:07:15.968408 | 
2025-10-04 00:07:15.968482 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-04 00:07:15.992317 | controller | skipping: Conditional result was False
2025-10-04 00:07:16.000473 | 
2025-10-04 00:07:16.000592 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-04 00:07:16.025120 | controller | skipping: Conditional result was False
2025-10-04 00:07:16.031650 | 
2025-10-04 00:07:16.031738 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-04 00:07:16.056044 | controller | skipping: Conditional result was False
2025-10-04 00:07:16.067810 | 
2025-10-04 00:07:16.067883 | TASK [Disable Fedora Modular]
2025-10-04 00:07:16.745006 | controller | changed
2025-10-04 00:07:16.753440 | 
2025-10-04 00:07:16.753521 | TASK [Enable EPEL]
2025-10-04 00:07:16.780905 | controller | skipping: Conditional result was False
2025-10-04 00:07:16.788590 | 
2025-10-04 00:07:16.788694 | TASK [Register the RHEL node]
2025-10-04 00:07:16.960267 | 
2025-10-04 00:07:16.960551 | TASK [Show the subscription-manager status]
2025-10-04 00:07:17.131094 | controller | skipping: Conditional result was False
2025-10-04 00:07:17.137805 | 
2025-10-04 00:07:17.137884 | TASK [Enable EPEL on RHEL]
2025-10-04 00:07:17.287229 | controller | skipping: Conditional result was False
2025-10-04 00:07:17.300073 | 
2025-10-04 00:07:17.300202 | TASK [Install git and tox]
2025-10-04 00:08:30.915177 | controller | changed
2025-10-04 00:08:30.934879 | 
2025-10-04 00:08:30.935149 | TASK [include_role : prepare-workspace]
2025-10-04 00:08:30.964538 | controller | ok
2025-10-04 00:08:31.002892 | 
2025-10-04 00:08:31.003067 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-04 00:08:31.557191 | controller | ok
2025-10-04 00:08:31.572804 | 
2025-10-04 00:08:31.572965 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-04 00:08:45.630224 | controller | Output suppressed because no_log was given
2025-10-04 00:08:45.642005 | 
2025-10-04 00:08:45.642131 | TASK [include_role : prepare-workspace-openshift]
2025-10-04 00:08:45.668750 | controller | skipping: Conditional result was False
2025-10-04 00:08:45.733894 | 
2025-10-04 00:08:45.733996 | PLAY [all:!appliance]
2025-10-04 00:08:45.748094 | 
2025-10-04 00:08:45.748168 | TASK [Run add-build-sshkey role (RSA)]
2025-10-04 00:08:45.777291 | controller | ok
2025-10-04 00:08:45.791801 | 
2025-10-04 00:08:45.791867 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-04 00:08:46.023426 | controller -> localhost | ok
2025-10-04 00:08:46.029991 | 
2025-10-04 00:08:46.030063 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-04 00:08:46.058757 | controller | ok
2025-10-04 00:08:46.072147 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-04 00:08:46.077853 | 
2025-10-04 00:08:46.077917 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-04 00:08:46.634512 | controller -> localhost | Generating public/private rsa key pair.
2025-10-04 00:08:46.634786 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_rsa.
2025-10-04 00:08:46.634822 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_rsa.pub.
2025-10-04 00:08:46.634848 | controller -> localhost | The key fingerprint is:
2025-10-04 00:08:46.634872 | controller -> localhost | SHA256:8D46f/fUgjC1GagsmflLabRPf9LiDI4JSbqYLJtypz8 zuul-build-sshkey
2025-10-04 00:08:46.634898 | controller -> localhost | The key's randomart image is:
2025-10-04 00:08:46.634921 | controller -> localhost | +---[RSA 2048]----+
2025-10-04 00:08:46.634943 | controller -> localhost | |                 |
2025-10-04 00:08:46.634966 | controller -> localhost | |           .     |
2025-10-04 00:08:46.634988 | controller -> localhost | |      .   . o    |
2025-10-04 00:08:46.635009 | controller -> localhost | |       B . . +   |
2025-10-04 00:08:46.635031 | controller -> localhost | |      * S o o    |
2025-10-04 00:08:46.635062 | controller -> localhost | |     o * o o . . |
2025-10-04 00:08:46.635087 | controller -> localhost | |    . o O o ..o .|
2025-10-04 00:08:46.635110 | controller -> localhost | |oo.oE..= O.++.o. |
2025-10-04 00:08:46.635133 | controller -> localhost | |++=+o..o=.oo+=.  |
2025-10-04 00:08:46.635157 | controller -> localhost | +----[SHA256]-----+
2025-10-04 00:08:46.635217 | controller -> localhost | ok: Runtime: 0:00:00.112178
2025-10-04 00:08:46.643171 | 
2025-10-04 00:08:46.643273 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-04 00:08:46.664054 | controller | ok
2025-10-04 00:08:46.673864 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-04 00:08:46.683373 | 
2025-10-04 00:08:46.683457 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-04 00:08:46.707953 | controller | skipping: Conditional result was False
2025-10-04 00:08:46.714812 | 
2025-10-04 00:08:46.714898 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-04 00:08:47.368793 | controller | changed
2025-10-04 00:08:47.381803 | 
2025-10-04 00:08:47.382053 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-04 00:08:47.742547 | controller | ok
2025-10-04 00:08:47.753767 | 
2025-10-04 00:08:47.753959 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-04 00:08:49.020925 | controller | changed
2025-10-04 00:08:49.031393 | 
2025-10-04 00:08:49.031528 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-04 00:08:50.340023 | controller | changed
2025-10-04 00:08:50.345510 | 
2025-10-04 00:08:50.345575 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-04 00:08:50.405274 | controller | skipping: Conditional result was False
2025-10-04 00:08:50.411907 | 
2025-10-04 00:08:50.411984 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-04 00:08:50.782094 | controller -> localhost | changed
2025-10-04 00:08:50.793243 | 
2025-10-04 00:08:50.793355 | TASK [add-build-sshkey : Add back temp key]
2025-10-04 00:08:51.177235 | controller -> localhost | Identity added: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_rsa (zuul-build-sshkey)
2025-10-04 00:08:51.177509 | controller -> localhost | ok: Runtime: 0:00:00.008655
2025-10-04 00:08:51.184872 | 
2025-10-04 00:08:51.184960 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-04 00:08:51.768284 | controller | ok
2025-10-04 00:08:51.777338 | 
2025-10-04 00:08:51.777446 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-04 00:08:51.815261 | controller | skipping: Conditional result was False
2025-10-04 00:08:51.835288 | 
2025-10-04 00:08:51.835466 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-04 00:08:51.869180 | controller | ok
2025-10-04 00:08:51.887837 | 
2025-10-04 00:08:51.887959 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-04 00:08:52.146391 | controller -> localhost | ok
2025-10-04 00:08:52.153107 | 
2025-10-04 00:08:52.153211 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-04 00:08:52.190158 | controller | ok
2025-10-04 00:08:52.202784 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-04 00:08:52.209030 | 
2025-10-04 00:08:52.209115 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-04 00:08:52.580596 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-04 00:08:52.580849 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_ecdsa.
2025-10-04 00:08:52.580882 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_ecdsa.pub.
2025-10-04 00:08:52.580911 | controller -> localhost | The key fingerprint is:
2025-10-04 00:08:52.580932 | controller -> localhost | SHA256:WMplrD241rFpAkh4ISKNTzhWGkngOw/+e0zSeBCuOxY zuul-build-sshkey
2025-10-04 00:08:52.580951 | controller -> localhost | The key's randomart image is:
2025-10-04 00:08:52.580970 | controller -> localhost | +---[ECDSA 521]---+
2025-10-04 00:08:52.580988 | controller -> localhost | |B*+.             |
2025-10-04 00:08:52.581005 | controller -> localhost | |B==o   .         |
2025-10-04 00:08:52.581022 | controller -> localhost | |o*+ .   =        |
2025-10-04 00:08:52.581040 | controller -> localhost | | oo+ . X         |
2025-10-04 00:08:52.581057 | controller -> localhost | | +o = * S        |
2025-10-04 00:08:52.581075 | controller -> localhost | |.E+o = o =       |
2025-10-04 00:08:52.581092 | controller -> localhost | | .o.= + =        |
2025-10-04 00:08:52.581109 | controller -> localhost | | +.  + o         |
2025-10-04 00:08:52.581125 | controller -> localhost | |. .oo            |
2025-10-04 00:08:52.581142 | controller -> localhost | +----[SHA256]-----+
2025-10-04 00:08:52.581193 | controller -> localhost | ok: Runtime: 0:00:00.008125
2025-10-04 00:08:52.591524 | 
2025-10-04 00:08:52.591636 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-04 00:08:52.612204 | controller | ok
2025-10-04 00:08:52.621352 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-04 00:08:52.634856 | 
2025-10-04 00:08:52.634978 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-04 00:08:52.660378 | controller | skipping: Conditional result was False
2025-10-04 00:08:52.667570 | 
2025-10-04 00:08:52.667664 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-04 00:08:53.111449 | controller | changed
2025-10-04 00:08:53.125364 | 
2025-10-04 00:08:53.125505 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-04 00:08:53.467878 | controller | ok
2025-10-04 00:08:53.477107 | 
2025-10-04 00:08:53.477211 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-04 00:08:54.799924 | controller | changed
2025-10-04 00:08:54.806163 | 
2025-10-04 00:08:54.806233 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-04 00:08:56.085660 | controller | changed
2025-10-04 00:08:56.091588 | 
2025-10-04 00:08:56.091677 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-04 00:08:56.106574 | controller | skipping: Conditional result was False
2025-10-04 00:08:56.121301 | 
2025-10-04 00:08:56.121460 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-04 00:08:56.426370 | controller -> localhost | changed
2025-10-04 00:08:56.437938 | 
2025-10-04 00:08:56.438018 | TASK [add-build-sshkey : Add back temp key]
2025-10-04 00:08:56.763926 | controller -> localhost | Identity added: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/395cb5ca03af4b1f9277eae39d6a0031_id_ecdsa (zuul-build-sshkey)
2025-10-04 00:08:56.764281 | controller -> localhost | ok: Runtime: 0:00:00.013500
2025-10-04 00:08:56.777880 | 
2025-10-04 00:08:56.778032 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-04 00:08:57.133668 | controller | ok
2025-10-04 00:08:57.142096 | 
2025-10-04 00:08:57.142258 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-04 00:08:57.190568 | controller | skipping: Conditional result was False
2025-10-04 00:08:57.206958 | 
2025-10-04 00:08:57.207084 | TASK [include_role : remove-zuul-sshkey]
2025-10-04 00:08:57.232966 | controller | skipping: Conditional result was False
2025-10-04 00:08:57.243366 | 
2025-10-04 00:08:57.243533 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-04 00:08:57.570973 | controller | ok: "logs"
2025-10-04 00:08:57.571481 | controller | ok: All items complete
2025-10-04 00:08:57.571540 | 
2025-10-04 00:08:57.846267 | controller | ok: "artifacts"
2025-10-04 00:08:58.121475 | controller | ok: "docs"
2025-10-04 00:08:58.141202 | 
2025-10-04 00:08:58.141610 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-04 00:08:58.471951 | controller | changed: "logs"
2025-10-04 00:08:58.751925 | controller | changed: "artifacts"
2025-10-04 00:08:59.036059 | controller | changed: "docs"
2025-10-04 00:08:59.068896 | 
2025-10-04 00:08:59.069014 | PLAY RECAP
2025-10-04 00:08:59.069059 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-04 00:08:59.069085 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-04 00:08:59.069108 | 
2025-10-04 00:08:59.211017 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-04 00:08:59.211972 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-04 00:08:59.793998 | 
2025-10-04 00:08:59.794110 | PLAY [all]
2025-10-04 00:08:59.815356 | 
2025-10-04 00:08:59.815469 | TASK [Install binary dependencies]
2025-10-04 00:08:59.875308 | controller | ok
2025-10-04 00:08:59.896461 | 
2025-10-04 00:08:59.896603 | TASK [bindep : Include find tasks]
2025-10-04 00:08:59.926529 | controller | ok
2025-10-04 00:08:59.934492 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-04 00:08:59.940914 | 
2025-10-04 00:08:59.940981 | TASK [bindep : Look for bindep.txt]
2025-10-04 00:09:00.486616 | controller | ok
2025-10-04 00:09:00.502949 | 
2025-10-04 00:09:00.503129 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:09:00.541137 | controller | skipping: Conditional result was False
2025-10-04 00:09:00.554623 | 
2025-10-04 00:09:00.554818 | TASK [bindep : Look for other-requirements.txt]
2025-10-04 00:09:00.863945 | controller | ok
2025-10-04 00:09:00.870384 | 
2025-10-04 00:09:00.870496 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:09:00.894987 | controller | skipping: Conditional result was False
2025-10-04 00:09:00.904450 | 
2025-10-04 00:09:00.904625 | TASK [bindep : Look for bindep fallback file]
2025-10-04 00:09:00.951213 | controller | skipping: Conditional result was False
2025-10-04 00:09:00.960877 | 
2025-10-04 00:09:00.960987 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:09:00.985090 | controller | skipping: Conditional result was False
2025-10-04 00:09:00.991341 | 
2025-10-04 00:09:00.991414 | TASK [bindep : Include bindep tasks]
2025-10-04 00:09:01.025058 | controller | skipping: Conditional result was False
2025-10-04 00:09:01.032848 | 
2025-10-04 00:09:01.032925 | TASK [bindep : Include install tasks]
2025-10-04 00:09:01.057575 | controller | skipping: Conditional result was False
2025-10-04 00:09:01.064525 | 
2025-10-04 00:09:01.064606 | LOOP [bindep : Include package tasks]
2025-10-04 00:09:01.126999 | 
2025-10-04 00:09:01.127210 | TASK [Run test-setup role]
2025-10-04 00:09:01.158480 | controller | ok
2025-10-04 00:09:01.177590 | 
2025-10-04 00:09:01.177674 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-04 00:09:01.494928 | controller | ok
2025-10-04 00:09:01.502452 | 
2025-10-04 00:09:01.502607 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-04 00:09:01.636731 | controller | skipping: Conditional result was False
2025-10-04 00:09:01.663234 | 
2025-10-04 00:09:01.663322 | PLAY RECAP
2025-10-04 00:09:01.663370 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-04 00:09:01.663395 | 
2025-10-04 00:09:01.777208 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-04 00:09:01.778985 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-04 00:09:02.410773 | 
2025-10-04 00:09:02.410938 | PLAY [controller]
2025-10-04 00:09:02.432446 | 
2025-10-04 00:09:02.432564 | TASK [Create the /root directory]
2025-10-04 00:09:03.171891 | controller | ok
2025-10-04 00:09:03.187107 | 
2025-10-04 00:09:03.187241 | TASK [Install glibc-langpack-en]
2025-10-04 00:09:11.388607 | controller | ok: Nothing to do
2025-10-04 00:09:11.406010 | 
2025-10-04 00:09:11.406182 | TASK [Ensure controller directory exists]
2025-10-04 00:09:11.836178 | controller | changed
2025-10-04 00:09:11.853169 | 
2025-10-04 00:09:11.853344 | TASK [Install container runtime]
2025-10-04 00:09:11.900177 | controller | ok
2025-10-04 00:09:11.949979 | 
2025-10-04 00:09:11.950101 | LOOP [ensure-podman : Find distribution installation]
2025-10-04 00:09:11.990300 | controller | ok: "/var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-04 00:09:12.006519 | controller | included: /var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-04 00:09:12.015115 | 
2025-10-04 00:09:12.015212 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-04 00:10:26.211172 | controller | changed
2025-10-04 00:10:26.220488 | 
2025-10-04 00:10:26.220592 | TASK [ensure-podman : Fetch podman version]
2025-10-04 00:10:26.959414 | controller | Client:       Podman Engine
2025-10-04 00:10:26.985321 | controller | Version:      4.6.2
2025-10-04 00:10:26.985363 | controller | API Version:  4.6.2
2025-10-04 00:10:26.985369 | controller | Go Version:   go1.19.12
2025-10-04 00:10:26.985398 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-04 00:10:26.985407 | controller | OS/Arch:      linux/amd64
2025-10-04 00:10:27.368741 | controller | ok: Runtime: 0:00:00.217610
2025-10-04 00:10:27.387041 | 
2025-10-04 00:10:27.387257 | TASK [ensure-podman : Print podman version installed]
2025-10-04 00:10:27.425110 | Podman version: Client:       Podman Engine
2025-10-04 00:10:27.425330 | Version:      4.6.2
2025-10-04 00:10:27.425428 | API Version:  4.6.2
2025-10-04 00:10:27.425475 | Go Version:   go1.19.12
2025-10-04 00:10:27.425511 | Built:        Mon Aug 28 19:38:31 2023
2025-10-04 00:10:27.425545 | OS/Arch:      linux/amd64
2025-10-04 00:10:27.433427 | 
2025-10-04 00:10:27.433524 | TASK [ensure-podman : Validate podman engine]
2025-10-04 00:10:27.579076 | controller | skipping: Conditional result was False
2025-10-04 00:10:27.586742 | 
2025-10-04 00:10:27.587039 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-04 00:10:27.601606 | controller | skipping: Conditional result was False
2025-10-04 00:10:27.614741 | 
2025-10-04 00:10:27.614868 | TASK [Ensure python3.8 is present]
2025-10-04 00:10:27.629384 | controller | skipping: Conditional result was False
2025-10-04 00:10:27.638284 | 
2025-10-04 00:10:27.638449 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-04 00:10:27.659665 | controller | ok
2025-10-04 00:10:27.681025 | 
2025-10-04 00:10:27.681146 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-04 00:10:31.450307 | controller | ok: Nothing to do
2025-10-04 00:10:31.470059 | 
2025-10-04 00:10:31.470300 | TASK [our-ensure-python : Also install python3-devel]
2025-10-04 00:10:44.740389 | controller | changed
2025-10-04 00:10:44.752643 | 
2025-10-04 00:10:44.752782 | TASK [Run ensure-virtualenv role]
2025-10-04 00:10:44.794145 | controller | ok
2025-10-04 00:10:44.818061 | 
2025-10-04 00:10:44.818211 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-04 00:10:45.179463 | controller | /usr/bin/virtualenv
2025-10-04 00:10:45.445912 | controller | ok: Runtime: 0:00:00.004527
2025-10-04 00:10:45.452168 | 
2025-10-04 00:10:45.452252 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-04 00:10:45.472433 | controller | skipping: Conditional result was False
2025-10-04 00:10:45.472763 | controller | ok: All items complete
2025-10-04 00:10:45.472804 | 
2025-10-04 00:10:45.551726 | 
2025-10-04 00:10:45.551863 | TASK [Find the full path of the Python interpreter]
2025-10-04 00:10:45.979900 | controller | /usr/bin/python3
2025-10-04 00:10:46.189869 | controller | ok
2025-10-04 00:10:46.196049 | 
2025-10-04 00:10:46.196151 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-04 00:10:47.693901 | controller | created virtual environment CPython3.11.0.final.0-64 in 768ms
2025-10-04 00:10:47.748323 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-04 00:10:47.749050 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-10-04 00:10:47.749182 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-04 00:10:47.749208 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-04 00:10:47.836515 | controller | changed
2025-10-04 00:10:47.853190 | 
2025-10-04 00:10:47.853362 | TASK [Set selinux package]
2025-10-04 00:10:47.886204 | controller | ok
2025-10-04 00:10:47.900284 | 
2025-10-04 00:10:47.900495 | TASK [Set selinux package (Fedora)]
2025-10-04 00:10:47.948757 | controller | ok
2025-10-04 00:10:47.957483 | 
2025-10-04 00:10:47.957609 | TASK [Install selinux into virtualenv]
2025-10-04 00:10:50.639905 | controller | Collecting selinux-please-lie-to-me
2025-10-04 00:10:50.728574 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-04 00:10:51.307534 | controller | Collecting setuptools<50.0.0
2025-10-04 00:10:51.351104 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-04 00:10:51.474483 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-10-04 00:10:51.628790 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-04 00:10:51.629201 | controller |   Attempting uninstall: setuptools
2025-10-04 00:10:51.634177 | controller |     Found existing installation: setuptools 62.6.0
2025-10-04 00:10:51.746030 | controller |     Uninstalling setuptools-62.6.0:
2025-10-04 00:10:51.761191 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-04 00:10:52.522045 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-04 00:10:52.734208 | controller |
2025-10-04 00:10:52.947156 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-04 00:10:52.947202 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-04 00:10:53.126730 | controller | ok: Runtime: 0:00:04.514697
2025-10-04 00:10:53.132836 | 
2025-10-04 00:10:53.132911 | TASK [Install pytest-forked into virtualenv]
2025-10-04 00:10:54.315375 | controller | Collecting pytest-forked
2025-10-04 00:10:54.400777 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-04 00:10:54.459678 | controller | Collecting py
2025-10-04 00:10:54.471555 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-04 00:10:54.508467 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-04 00:10:54.685408 | controller | Collecting pytest>=3.10
2025-10-04 00:10:54.696994 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-04 00:10:54.757957 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-04 00:10:54.810956 | controller | Collecting iniconfig>=1
2025-10-04 00:10:54.822830 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-04 00:10:54.889610 | controller | Collecting packaging>=20
2025-10-04 00:10:54.901274 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-04 00:10:54.913473 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00
2025-10-04 00:10:54.959952 | controller | Collecting pluggy<2,>=1.5
2025-10-04 00:10:54.971684 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-04 00:10:55.048027 | controller | Collecting pygments>=2.7.2
2025-10-04 00:10:55.060391 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-04 00:10:55.177047 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.8 MB/s eta 0:00:00
2025-10-04 00:10:55.311903 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-04 00:10:57.611559 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-04 00:10:57.628044 | controller |
2025-10-04 00:10:57.815988 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-04 00:10:57.816041 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-04 00:10:58.281933 | controller | ok: Runtime: 0:00:04.224693
2025-10-04 00:10:58.298335 | 
2025-10-04 00:10:58.298596 | TASK [Update pip]
2025-10-04 00:10:59.439833 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-04 00:10:59.733625 | controller | Collecting pip
2025-10-04 00:10:59.831416 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-04 00:10:59.995306 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.0 MB/s eta 0:00:00
2025-10-04 00:11:00.157607 | controller | Installing collected packages: pip
2025-10-04 00:11:00.158059 | controller |   Attempting uninstall: pip
2025-10-04 00:11:00.162726 | controller |     Found existing installation: pip 22.2.2
2025-10-04 00:11:00.421296 | controller |     Uninstalling pip-22.2.2:
2025-10-04 00:11:00.451242 | controller |       Successfully uninstalled pip-22.2.2
2025-10-04 00:11:02.225894 | controller | Successfully installed pip-25.2
2025-10-04 00:11:02.984350 | controller | ok: Runtime: 0:00:03.605334
2025-10-04 00:11:02.995451 | 
2025-10-04 00:11:02.995554 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-04 00:11:03.594045 | controller | changed
2025-10-04 00:11:03.599723 | 
2025-10-04 00:11:03.599816 | TASK [Install ansible into virtualenv]
2025-10-04 00:11:04.778000 | controller | Processing ./src/github.com/ansible/ansible
2025-10-04 00:11:04.784328 | controller |   Installing build dependencies: started
2025-10-04 00:11:06.706209 | controller |   Installing build dependencies: finished with status 'done'
2025-10-04 00:11:08.382384 | controller |   Getting requirements to build wheel: started
2025-10-04 00:11:08.382448 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-04 00:11:09.296578 | controller |   Preparing metadata (pyproject.toml): started
2025-10-04 00:11:09.296633 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-04 00:11:09.300142 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-10-04 00:11:09.304877 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-04 00:11:09.765812 | controller | ERROR
2025-10-04 00:11:09.765984 | controller | {
2025-10-04 00:11:09.766013 | controller |   "delta": "0:00:05.370351",
2025-10-04 00:11:09.766034 | controller |   "end": "2025-10-04 00:11:09.452602",
2025-10-04 00:11:09.766052 | controller |   "msg": "non-zero return code",
2025-10-04 00:11:09.766076 | controller |   "rc": 1,
2025-10-04 00:11:09.766093 | controller |   "start": "2025-10-04 00:11:04.082251"
2025-10-04 00:11:09.766110 | controller | }
failure
2025-10-04 00:11:09.767703 | 
2025-10-04 00:11:09.767751 | PLAY RECAP
2025-10-04 00:11:09.767792 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-04 00:11:09.767813 | 
2025-10-04 00:11:09.909629 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-04 00:11:09.911537 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-04 00:11:10.570498 | 
2025-10-04 00:11:10.570642 | PLAY [all]
2025-10-04 00:11:10.595938 | 
2025-10-04 00:11:10.596083 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-04 00:11:11.373341 | controller | changed: non-zero return code
2025-10-04 00:11:11.379439 | 
2025-10-04 00:11:11.379519 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-04 00:11:11.404944 | controller | skipping: Conditional result was False
2025-10-04 00:11:11.411427 | 
2025-10-04 00:11:11.411501 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-04 00:11:11.433948 | 
2025-10-04 00:11:11.434100 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-04 00:11:11.474703 | 
2025-10-04 00:11:11.474870 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-04 00:11:11.499600 | controller | skipping: Conditional result was False
2025-10-04 00:11:11.510438 | 
2025-10-04 00:11:11.510562 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-04 00:11:11.546272 | 
2025-10-04 00:11:11.546493 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-04 00:11:11.571919 | controller | skipping: Conditional result was False
2025-10-04 00:11:11.581234 | 
2025-10-04 00:11:11.581355 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-04 00:11:11.606954 | controller | skipping: Conditional result was False
2025-10-04 00:11:11.615994 | 
2025-10-04 00:11:11.616080 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-04 00:11:11.640168 | controller | skipping: Conditional result was False
2025-10-04 00:11:11.688672 | 
2025-10-04 00:11:11.688800 | PLAY RECAP
2025-10-04 00:11:11.688843 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-04 00:11:11.688864 | 
2025-10-04 00:11:11.803478 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-04 00:11:11.804669 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-04 00:11:12.484726 | 
2025-10-04 00:11:12.484935 | PLAY [all:!appliance*]
2025-10-04 00:11:12.523462 | 
2025-10-04 00:11:12.523605 | TASK [unregister the node]
2025-10-04 00:11:12.663897 | controller | skipping: Conditional result was False
2025-10-04 00:11:12.676047 | 
2025-10-04 00:11:12.676232 | TASK [include_role : fetch-output]
2025-10-04 00:11:12.722159 | controller | ok
2025-10-04 00:11:12.755547 | 
2025-10-04 00:11:12.755756 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-04 00:11:12.829098 | controller | skipping: Conditional result was False
2025-10-04 00:11:12.835794 | 
2025-10-04 00:11:12.835944 | TASK [fetch-output : Set log path for single node]
2025-10-04 00:11:12.875956 | controller | ok
2025-10-04 00:11:12.882018 | 
2025-10-04 00:11:12.882139 | LOOP [fetch-output : Ensure local output dirs]
2025-10-04 00:11:13.254993 | controller -> localhost | ok: "/var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/logs"
2025-10-04 00:11:13.453198 | controller -> localhost | changed: "/var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/artifacts"
2025-10-04 00:11:13.679666 | controller -> localhost | changed: "/var/lib/zuul/builds/395cb5ca03af4b1f9277eae39d6a0031/work/docs"
2025-10-04 00:11:13.697654 | 
2025-10-04 00:11:13.697813 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-04 00:11:14.974630 | controller | changed:
2025-10-04 00:11:14.974867 | controller | .d..t...... ./
2025-10-04 00:11:14.974895 | controller | cd+++++++++ controller/
2025-10-04 00:11:14.974930 | controller | changed: All items complete
2025-10-04 00:11:14.974950 | 
2025-10-04 00:11:15.978952 | controller | changed: .d..t...... ./
2025-10-04 00:11:17.033165 | controller | changed: .d..t...... ./
2025-10-04 00:11:17.055617 | 
2025-10-04 00:11:17.055788 | TASK [include_role : fetch-output-openshift]
2025-10-04 00:11:17.081472 | controller | skipping: Conditional result was False
2025-10-04 00:11:17.090481 | 
2025-10-04 00:11:17.090624 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-04 00:11:17.118586 | controller | skipping: Conditional result was False
2025-10-04 00:11:17.129857 | controller | skipping: Conditional result was False
2025-10-04 00:11:17.185327 | 
2025-10-04 00:11:17.185446 | PLAY [localhost]
2025-10-04 00:11:17.216717 | 
2025-10-04 00:11:17.217014 | TASK [Run Zuul manifest role]
2025-10-04 00:11:17.239173 | localhost | ok
2025-10-04 00:11:17.258451 | 
2025-10-04 00:11:17.258595 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-04 00:11:17.679557 | localhost | changed
2025-10-04 00:11:17.689292 | 
2025-10-04 00:11:17.689462 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-04 00:11:17.732145 | localhost | ok
2025-10-04 00:11:17.750096 | 
2025-10-04 00:11:17.750292 | TASK [Set zuul-log-path fact]
2025-10-04 00:11:17.777051 | localhost | ok
2025-10-04 00:11:17.794107 | 
2025-10-04 00:11:17.794270 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-04 00:11:17.823736 | localhost | ok
2025-10-04 00:11:17.834399 | 
2025-10-04 00:11:17.834731 | LOOP [Run upload-logs-swift role]
2025-10-04 00:11:17.858936 | localhost | Output suppressed because no_log was given
2025-10-04 00:11:17.882855 | 
2025-10-04 00:11:17.883091 | TASK [Set zuul-log-path fact]
2025-10-04 00:11:17.907375 | localhost | skipping: Conditional result was False
2025-10-04 00:11:17.912541 | 
2025-10-04 00:11:17.912615 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-04 00:11:18.397113 | localhost -> localhost | ok: Runtime: 0:00:00.005997
2025-10-04 00:11:18.402538 | 
2025-10-04 00:11:18.402639 | TASK [upload-logs-swift : Upload logs to swift]