2025-10-21 00:06:40.324183 | Job console starting...
2025-10-21 00:06:40.337348 | Updating repositories
2025-10-21 00:06:43.341776 | Preparing job workspace
2025-10-21 00:06:48.605884 | Running Ansible setup...
2025-10-21 00:06:54.646270 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-21 00:06:55.309220 | 
2025-10-21 00:06:55.309395 | PLAY [localhost]
2025-10-21 00:06:55.318652 | 
2025-10-21 00:06:55.318782 | TASK [Gathering Facts]
2025-10-21 00:06:56.442331 | localhost | ok
2025-10-21 00:06:56.460722 | 
2025-10-21 00:06:56.460861 | TASK [Setup log path fact]
2025-10-21 00:06:56.480035 | localhost | ok
2025-10-21 00:06:56.494137 | 
2025-10-21 00:06:56.494245 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-21 00:06:56.524172 | localhost | ok
2025-10-21 00:06:56.538276 | 
2025-10-21 00:06:56.538397 | TASK [emit-job-header : Print job information]
2025-10-21 00:06:56.576512 | # Job Information
2025-10-21 00:06:56.576687 | Ansible Version: 2.15.12
2025-10-21 00:06:56.576724 | Job: ansible-test-sanity-docker-devel
2025-10-21 00:06:56.576746 | Pipeline: periodic
2025-10-21 00:06:56.576764 | Executor: ze02.softwarefactory-project.io
2025-10-21 00:06:56.576782 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-21 00:06:56.576803 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/150/ansible/15080781a79f4813afe5a750711ee202/
2025-10-21 00:06:56.576822 | Event ID: b84420a1d3514a69852f0a57fcb9cd72
2025-10-21 00:06:56.591202 | 
2025-10-21 00:06:56.591336 | LOOP [emit-job-header : Print node information]
2025-10-21 00:06:56.752274 | localhost | ok:
2025-10-21 00:06:56.752555 | localhost | # Node Information
2025-10-21 00:06:56.752587 | localhost | Inventory Hostname: controller
2025-10-21 00:06:56.752608 | localhost | Hostname: ip-172-16-3-159
2025-10-21 00:06:56.752627 | localhost | Username: zuul-worker
2025-10-21 00:06:56.752648 | localhost | Distro: Fedora 37
2025-10-21 00:06:56.752681 | localhost | Provider: ansible-us-east-2
2025-10-21 00:06:56.752703 | localhost | Region: us-east-2
2025-10-21 00:06:56.752721 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-21 00:06:56.752738 | localhost | Product Name: t3.small
2025-10-21 00:06:56.752754 | localhost | Interface IP: 3.140.246.31
2025-10-21 00:06:56.770217 | 
2025-10-21 00:06:56.770623 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-21 00:06:57.275958 | localhost -> localhost | changed
2025-10-21 00:06:57.287998 | 
2025-10-21 00:06:57.288096 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-21 00:06:58.128000 | localhost -> localhost | changed
2025-10-21 00:06:58.170448 | 
2025-10-21 00:06:58.170533 | PLAY [all:!appliance*]
2025-10-21 00:06:58.209729 | 
2025-10-21 00:06:58.209808 | TASK [include_role : start-zuul-console]
2025-10-21 00:06:58.231868 | controller | ok
2025-10-21 00:06:58.248264 | 
2025-10-21 00:06:58.248335 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-21 00:06:58.940590 | controller | ok
2025-10-21 00:06:58.963511 | 
2025-10-21 00:06:58.963625 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-21 00:07:00.473635 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-21 00:07:00.487578 | 
2025-10-21 00:07:00.487763 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-21 00:07:00.634077 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.642917 | 
2025-10-21 00:07:00.643010 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-21 00:07:00.678647 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.687225 | 
2025-10-21 00:07:00.687329 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-21 00:07:00.712724 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.721356 | 
2025-10-21 00:07:00.721450 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-21 00:07:00.755940 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.764354 | 
2025-10-21 00:07:00.764445 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-21 00:07:00.799946 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.809242 | 
2025-10-21 00:07:00.809354 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-21 00:07:00.843182 | controller | skipping: Conditional result was False
2025-10-21 00:07:00.860807 | 
2025-10-21 00:07:00.860966 | TASK [Disable Fedora Modular]
2025-10-21 00:07:01.635680 | controller | changed
2025-10-21 00:07:01.641416 | 
2025-10-21 00:07:01.641478 | TASK [Enable EPEL]
2025-10-21 00:07:01.677150 | controller | skipping: Conditional result was False
2025-10-21 00:07:01.686160 | 
2025-10-21 00:07:01.686276 | TASK [Register the RHEL node]
2025-10-21 00:07:01.852652 | 
2025-10-21 00:07:01.852855 | TASK [Show the subscription-manager status]
2025-10-21 00:07:02.045042 | controller | skipping: Conditional result was False
2025-10-21 00:07:02.052486 | 
2025-10-21 00:07:02.052601 | TASK [Enable EPEL on RHEL]
2025-10-21 00:07:02.203581 | controller | skipping: Conditional result was False
2025-10-21 00:07:02.209976 | 
2025-10-21 00:07:02.210052 | TASK [Install git and tox]
2025-10-21 00:08:30.780246 | controller | changed
2025-10-21 00:08:30.793416 | 
2025-10-21 00:08:30.793561 | TASK [include_role : prepare-workspace]
2025-10-21 00:08:30.837826 | controller | ok
2025-10-21 00:08:30.877250 | 
2025-10-21 00:08:30.877372 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-21 00:08:31.478524 | controller | ok
2025-10-21 00:08:31.492446 | 
2025-10-21 00:08:31.492590 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-21 00:08:45.843258 | controller | Output suppressed because no_log was given
2025-10-21 00:08:45.859406 | 
2025-10-21 00:08:45.859525 | TASK [include_role : prepare-workspace-openshift]
2025-10-21 00:08:45.885059 | controller | skipping: Conditional result was False
2025-10-21 00:08:45.918976 | 
2025-10-21 00:08:45.919118 | PLAY [all:!appliance]
2025-10-21 00:08:45.971433 | 
2025-10-21 00:08:45.971727 | TASK [Run add-build-sshkey role (RSA)]
2025-10-21 00:08:45.993198 | controller | ok
2025-10-21 00:08:46.008226 | 
2025-10-21 00:08:46.008299 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-21 00:08:46.256642 | controller -> localhost | ok
2025-10-21 00:08:46.264359 | 
2025-10-21 00:08:46.264436 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-21 00:08:46.288540 | controller | ok
2025-10-21 00:08:46.302892 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-21 00:08:46.309021 | 
2025-10-21 00:08:46.309084 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-21 00:08:46.849501 | controller -> localhost | Generating public/private rsa key pair.
2025-10-21 00:08:46.849907 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_rsa.
2025-10-21 00:08:46.849939 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_rsa.pub.
2025-10-21 00:08:46.849961 | controller -> localhost | The key fingerprint is:
2025-10-21 00:08:46.849981 | controller -> localhost | SHA256:2on7C0hbramde/RCWF5lc0oSJz7qNCnhW6ileISFPz8 zuul-build-sshkey
2025-10-21 00:08:46.850001 | controller -> localhost | The key's randomart image is:
2025-10-21 00:08:46.850020 | controller -> localhost | +---[RSA 2048]----+
2025-10-21 00:08:46.850038 | controller -> localhost | |          o..    |
2025-10-21 00:08:46.850057 | controller -> localhost | |   .     ..o= .  |
2025-10-21 00:08:46.850076 | controller -> localhost | |  . . .   o= +   |
2025-10-21 00:08:46.850094 | controller -> localhost | |   + . +.o...    |
2025-10-21 00:08:46.850111 | controller -> localhost | |  . = *+S.       |
2025-10-21 00:08:46.850142 | controller -> localhost | |   + X.%+o       |
2025-10-21 00:08:46.850167 | controller -> localhost | |  . * Eo+.       |
2025-10-21 00:08:46.850186 | controller -> localhost | |   . o =o .      |
2025-10-21 00:08:46.850205 | controller -> localhost | |    . =+oo       |
2025-10-21 00:08:46.850227 | controller -> localhost | +----[SHA256]-----+
2025-10-21 00:08:46.850272 | controller -> localhost | ok: Runtime: 0:00:00.187324
2025-10-21 00:08:46.856825 | 
2025-10-21 00:08:46.856895 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-21 00:08:46.887052 | controller | ok
2025-10-21 00:08:46.896501 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-21 00:08:46.905131 | 
2025-10-21 00:08:46.905208 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-21 00:08:46.929533 | controller | skipping: Conditional result was False
2025-10-21 00:08:46.936241 | 
2025-10-21 00:08:46.936305 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-21 00:08:47.634657 | controller | changed
2025-10-21 00:08:47.647622 | 
2025-10-21 00:08:47.647821 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-21 00:08:48.026162 | controller | ok
2025-10-21 00:08:48.038634 | 
2025-10-21 00:08:48.038802 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-21 00:08:49.453495 | controller | changed
2025-10-21 00:08:49.466234 | 
2025-10-21 00:08:49.466368 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-21 00:08:51.173093 | controller | changed
2025-10-21 00:08:51.186729 | 
2025-10-21 00:08:51.187111 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-21 00:08:51.214798 | controller | skipping: Conditional result was False
2025-10-21 00:08:51.225015 | 
2025-10-21 00:08:51.225132 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-21 00:08:51.698724 | controller -> localhost | changed
2025-10-21 00:08:51.710910 | 
2025-10-21 00:08:51.710988 | TASK [add-build-sshkey : Add back temp key]
2025-10-21 00:08:52.074163 | controller -> localhost | Identity added: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_rsa (zuul-build-sshkey)
2025-10-21 00:08:52.074516 | controller -> localhost | ok: Runtime: 0:00:00.013742
2025-10-21 00:08:52.083856 | 
2025-10-21 00:08:52.083942 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-21 00:08:52.648540 | controller | ok
2025-10-21 00:08:52.656061 | 
2025-10-21 00:08:52.656184 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-21 00:08:52.682336 | controller | skipping: Conditional result was False
2025-10-21 00:08:52.698274 | 
2025-10-21 00:08:52.698366 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-21 00:08:52.722103 | controller | ok
2025-10-21 00:08:52.746260 | 
2025-10-21 00:08:52.746401 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-21 00:08:53.008418 | controller -> localhost | ok
2025-10-21 00:08:53.014585 | 
2025-10-21 00:08:53.014650 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-21 00:08:53.045608 | controller | ok
2025-10-21 00:08:53.056586 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-21 00:08:53.062546 | 
2025-10-21 00:08:53.062608 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-21 00:08:53.372322 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-21 00:08:53.372711 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_ecdsa.
2025-10-21 00:08:53.372787 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_ecdsa.pub.
2025-10-21 00:08:53.372877 | controller -> localhost | The key fingerprint is:
2025-10-21 00:08:53.372926 | controller -> localhost | SHA256:ubow5jrmqt58JMkcbBJIx/iSNUWsRgc20+uRFMSkwK8 zuul-build-sshkey
2025-10-21 00:08:53.372971 | controller -> localhost | The key's randomart image is:
2025-10-21 00:08:53.373015 | controller -> localhost | +---[ECDSA 521]---+
2025-10-21 00:08:53.373058 | controller -> localhost | |+oo*X*.          |
2025-10-21 00:08:53.373100 | controller -> localhost | |.++=+*           |
2025-10-21 00:08:53.373142 | controller -> localhost | |  O.= o          |
2025-10-21 00:08:53.373183 | controller -> localhost | | + O +   .       |
2025-10-21 00:08:53.373226 | controller -> localhost | |  O + . S        |
2025-10-21 00:08:53.373267 | controller -> localhost | | E = o   .       |
2025-10-21 00:08:53.373308 | controller -> localhost | |    *   .        |
2025-10-21 00:08:53.373349 | controller -> localhost | |  =o + .         |
2025-10-21 00:08:53.373389 | controller -> localhost | |==o=o o.         |
2025-10-21 00:08:53.373430 | controller -> localhost | +----[SHA256]-----+
2025-10-21 00:08:53.373558 | controller -> localhost | ok: Runtime: 0:00:00.012872
2025-10-21 00:08:53.388473 | 
2025-10-21 00:08:53.388622 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-21 00:08:53.418182 | controller | ok
2025-10-21 00:08:53.433826 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-21 00:08:53.447367 | 
2025-10-21 00:08:53.447543 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-21 00:08:53.475047 | controller | skipping: Conditional result was False
2025-10-21 00:08:53.484444 | 
2025-10-21 00:08:53.484539 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-21 00:08:54.001888 | controller | changed
2025-10-21 00:08:54.010839 | 
2025-10-21 00:08:54.011015 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-21 00:08:54.400800 | controller | ok
2025-10-21 00:08:54.406705 | 
2025-10-21 00:08:54.406776 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-21 00:08:56.057992 | controller | changed
2025-10-21 00:08:56.073326 | 
2025-10-21 00:08:56.073475 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-21 00:08:57.807157 | controller | changed
2025-10-21 00:08:57.820634 | 
2025-10-21 00:08:57.820823 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-21 00:08:57.857957 | controller | skipping: Conditional result was False
2025-10-21 00:08:57.872376 | 
2025-10-21 00:08:57.872522 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-21 00:08:58.196757 | controller -> localhost | changed
2025-10-21 00:08:58.208134 | 
2025-10-21 00:08:58.208220 | TASK [add-build-sshkey : Add back temp key]
2025-10-21 00:08:58.528987 | controller -> localhost | Identity added: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/15080781a79f4813afe5a750711ee202_id_ecdsa (zuul-build-sshkey)
2025-10-21 00:08:58.529212 | controller -> localhost | ok: Runtime: 0:00:00.009801
2025-10-21 00:08:58.568488 | 
2025-10-21 00:08:58.568621 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-21 00:08:58.953882 | controller | ok
2025-10-21 00:08:58.959952 | 
2025-10-21 00:08:58.960069 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-21 00:08:58.988514 | controller | skipping: Conditional result was False
2025-10-21 00:08:59.000764 | 
2025-10-21 00:08:59.000888 | TASK [include_role : remove-zuul-sshkey]
2025-10-21 00:08:59.036016 | controller | skipping: Conditional result was False
2025-10-21 00:08:59.042858 | 
2025-10-21 00:08:59.043135 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-21 00:08:59.377187 | controller | ok: "logs"
2025-10-21 00:08:59.377448 | controller | ok: All items complete
2025-10-21 00:08:59.377481 | 
2025-10-21 00:08:59.672367 | controller | ok: "artifacts"
2025-10-21 00:08:59.966016 | controller | ok: "docs"
2025-10-21 00:08:59.984773 | 
2025-10-21 00:08:59.984935 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-21 00:09:00.442273 | controller | changed: "logs"
2025-10-21 00:09:00.783800 | controller | changed: "artifacts"
2025-10-21 00:09:01.086460 | controller | changed: "docs"
2025-10-21 00:09:01.141648 | 
2025-10-21 00:09:01.141865 | PLAY RECAP
2025-10-21 00:09:01.141927 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-21 00:09:01.141962 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-21 00:09:01.141987 | 
2025-10-21 00:09:01.273887 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-21 00:09:01.276207 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-21 00:09:01.828557 | 
2025-10-21 00:09:01.828693 | PLAY [all]
2025-10-21 00:09:01.850847 | 
2025-10-21 00:09:01.850943 | TASK [Install binary dependencies]
2025-10-21 00:09:01.900845 | controller | ok
2025-10-21 00:09:01.920109 | 
2025-10-21 00:09:01.920194 | TASK [bindep : Include find tasks]
2025-10-21 00:09:01.959131 | controller | ok
2025-10-21 00:09:01.966779 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-21 00:09:01.972796 | 
2025-10-21 00:09:01.972859 | TASK [bindep : Look for bindep.txt]
2025-10-21 00:09:02.871133 | controller | ok
2025-10-21 00:09:02.881686 | 
2025-10-21 00:09:02.881800 | TASK [bindep : Define bindep_file fact]
2025-10-21 00:09:02.910117 | controller | skipping: Conditional result was False
2025-10-21 00:09:02.921622 | 
2025-10-21 00:09:02.921746 | TASK [bindep : Look for other-requirements.txt]
2025-10-21 00:09:03.385102 | controller | ok
2025-10-21 00:09:03.393567 | 
2025-10-21 00:09:03.393727 | TASK [bindep : Define bindep_file fact]
2025-10-21 00:09:03.433082 | controller | skipping: Conditional result was False
2025-10-21 00:09:03.444615 | 
2025-10-21 00:09:03.444770 | TASK [bindep : Look for bindep fallback file]
2025-10-21 00:09:03.489618 | controller | skipping: Conditional result was False
2025-10-21 00:09:03.499900 | 
2025-10-21 00:09:03.500024 | TASK [bindep : Define bindep_file fact]
2025-10-21 00:09:03.535546 | controller | skipping: Conditional result was False
2025-10-21 00:09:03.548357 | 
2025-10-21 00:09:03.548495 | TASK [bindep : Include bindep tasks]
2025-10-21 00:09:03.587262 | controller | skipping: Conditional result was False
2025-10-21 00:09:03.594357 | 
2025-10-21 00:09:03.594430 | TASK [bindep : Include install tasks]
2025-10-21 00:09:03.630540 | controller | skipping: Conditional result was False
2025-10-21 00:09:03.645616 | 
2025-10-21 00:09:03.645743 | LOOP [bindep : Include package tasks]
2025-10-21 00:09:03.740036 | 
2025-10-21 00:09:03.740478 | TASK [Run test-setup role]
2025-10-21 00:09:03.768828 | controller | ok
2025-10-21 00:09:03.800484 | 
2025-10-21 00:09:03.800677 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-21 00:09:04.190528 | controller | ok
2025-10-21 00:09:04.199571 | 
2025-10-21 00:09:04.199789 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-21 00:09:04.358359 | controller | skipping: Conditional result was False
2025-10-21 00:09:04.402189 | 
2025-10-21 00:09:04.402401 | PLAY RECAP
2025-10-21 00:09:04.402468 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-21 00:09:04.402644 | 
2025-10-21 00:09:04.554368 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-21 00:09:04.555386 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-21 00:09:05.207628 | 
2025-10-21 00:09:05.207796 | PLAY [controller]
2025-10-21 00:09:05.226857 | 
2025-10-21 00:09:05.226940 | TASK [Create the /root directory]
2025-10-21 00:09:05.983115 | controller | ok
2025-10-21 00:09:05.995826 | 
2025-10-21 00:09:05.996034 | TASK [Install glibc-langpack-en]
2025-10-21 00:09:14.180381 | controller | ok: Nothing to do
2025-10-21 00:09:14.192722 | 
2025-10-21 00:09:14.192917 | TASK [Ensure controller directory exists]
2025-10-21 00:09:14.632694 | controller | changed
2025-10-21 00:09:14.645263 | 
2025-10-21 00:09:14.645424 | TASK [Install container runtime]
2025-10-21 00:09:14.733915 | controller | ok
2025-10-21 00:09:14.779193 | 
2025-10-21 00:09:14.779349 | LOOP [ensure-podman : Find distribution installation]
2025-10-21 00:09:14.815727 | controller | ok: "/var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-21 00:09:14.832097 | controller | included: /var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-21 00:09:14.849719 | 
2025-10-21 00:09:14.849873 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-21 00:10:32.543034 | controller | changed
2025-10-21 00:10:32.556945 | 
2025-10-21 00:10:32.557057 | TASK [ensure-podman : Fetch podman version]
2025-10-21 00:10:33.290070 | controller | Client:       Podman Engine
2025-10-21 00:10:33.313625 | controller | Version:      4.6.2
2025-10-21 00:10:33.313665 | controller | API Version:  4.6.2
2025-10-21 00:10:33.313672 | controller | Go Version:   go1.19.12
2025-10-21 00:10:33.313689 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-21 00:10:33.313697 | controller | OS/Arch:      linux/amd64
2025-10-21 00:10:33.724177 | controller | ok: Runtime: 0:00:00.215546
2025-10-21 00:10:33.730853 | 
2025-10-21 00:10:33.730928 | TASK [ensure-podman : Print podman version installed]
2025-10-21 00:10:33.760650 | Podman version: Client:       Podman Engine
2025-10-21 00:10:33.760831 | Version:      4.6.2
2025-10-21 00:10:33.760861 | API Version:  4.6.2
2025-10-21 00:10:33.760881 | Go Version:   go1.19.12
2025-10-21 00:10:33.760899 | Built:        Mon Aug 28 19:38:31 2023
2025-10-21 00:10:33.760919 | OS/Arch:      linux/amd64
2025-10-21 00:10:33.766355 | 
2025-10-21 00:10:33.766416 | TASK [ensure-podman : Validate podman engine]
2025-10-21 00:10:33.914390 | controller | skipping: Conditional result was False
2025-10-21 00:10:33.921380 | 
2025-10-21 00:10:33.921464 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-21 00:10:33.945783 | controller | skipping: Conditional result was False
2025-10-21 00:10:33.959317 | 
2025-10-21 00:10:33.959430 | TASK [Ensure python3.8 is present]
2025-10-21 00:10:33.974177 | controller | skipping: Conditional result was False
2025-10-21 00:10:33.981902 | 
2025-10-21 00:10:33.981994 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-21 00:10:34.006045 | controller | ok
2025-10-21 00:10:34.033250 | 
2025-10-21 00:10:34.033385 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-21 00:10:37.712619 | controller | ok: Nothing to do
2025-10-21 00:10:37.724029 | 
2025-10-21 00:10:37.724188 | TASK [our-ensure-python : Also install python3-devel]
2025-10-21 00:10:50.917261 | controller | changed
2025-10-21 00:10:50.930508 | 
2025-10-21 00:10:50.930603 | TASK [Run ensure-virtualenv role]
2025-10-21 00:10:50.987038 | controller | ok
2025-10-21 00:10:51.037369 | 
2025-10-21 00:10:51.037486 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-21 00:10:51.521949 | controller | /usr/bin/virtualenv
2025-10-21 00:10:51.706398 | controller | ok: Runtime: 0:00:00.005076
2025-10-21 00:10:51.715821 | 
2025-10-21 00:10:51.715985 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-21 00:10:51.762271 | controller | skipping: Conditional result was False
2025-10-21 00:10:51.762622 | controller | ok: All items complete
2025-10-21 00:10:51.762684 | 
2025-10-21 00:10:51.790744 | 
2025-10-21 00:10:51.790913 | TASK [Find the full path of the Python interpreter]
2025-10-21 00:10:52.299332 | controller | /usr/bin/python3
2025-10-21 00:10:52.474130 | controller | ok
2025-10-21 00:10:52.492778 | 
2025-10-21 00:10:52.493039 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-21 00:10:53.964962 | controller | created virtual environment CPython3.11.0.final.0-64 in 736ms
2025-10-21 00:10:54.021173 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-21 00:10:54.021232 | 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-21 00:10:54.021252 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-21 00:10:54.021276 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-21 00:10:54.182994 | controller | changed
2025-10-21 00:10:54.203992 | 
2025-10-21 00:10:54.204113 | TASK [Set selinux package]
2025-10-21 00:10:54.256812 | controller | ok
2025-10-21 00:10:54.272758 | 
2025-10-21 00:10:54.272895 | TASK [Set selinux package (Fedora)]
2025-10-21 00:10:54.354282 | controller | ok
2025-10-21 00:10:54.360355 | 
2025-10-21 00:10:54.360455 | TASK [Install selinux into virtualenv]
2025-10-21 00:10:57.019778 | controller | Collecting selinux-please-lie-to-me
2025-10-21 00:10:57.143981 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-21 00:10:57.671992 | controller | Collecting setuptools<50.0.0
2025-10-21 00:10:57.704502 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-21 00:10:57.827470 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.0 MB/s eta 0:00:00
2025-10-21 00:10:57.981923 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-21 00:10:57.982222 | controller |   Attempting uninstall: setuptools
2025-10-21 00:10:57.987122 | controller |     Found existing installation: setuptools 62.6.0
2025-10-21 00:10:58.097681 | controller |     Uninstalling setuptools-62.6.0:
2025-10-21 00:10:58.112731 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-21 00:10:58.850910 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-21 00:10:59.062900 | controller |
2025-10-21 00:10:59.270820 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-21 00:10:59.270867 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-21 00:10:59.558214 | controller | ok: Runtime: 0:00:04.411423
2025-10-21 00:10:59.566726 | 
2025-10-21 00:10:59.566867 | TASK [Install pytest-forked into virtualenv]
2025-10-21 00:11:00.811441 | controller | Collecting pytest-forked
2025-10-21 00:11:00.895820 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-21 00:11:00.958054 | controller | Collecting py
2025-10-21 00:11:00.970203 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-21 00:11:01.006297 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-10-21 00:11:01.179820 | controller | Collecting pytest>=3.10
2025-10-21 00:11:01.194814 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-21 00:11:01.255063 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.4 MB/s eta 0:00:00
2025-10-21 00:11:01.313864 | controller | Collecting iniconfig>=1
2025-10-21 00:11:01.326847 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-21 00:11:01.398542 | controller | Collecting packaging>=20
2025-10-21 00:11:01.410962 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-21 00:11:01.425912 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.2 MB/s eta 0:00:00
2025-10-21 00:11:01.475447 | controller | Collecting pluggy<2,>=1.5
2025-10-21 00:11:01.487447 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-21 00:11:01.619886 | controller | Collecting pygments>=2.7.2
2025-10-21 00:11:01.631827 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-21 00:11:01.767078 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.3 MB/s eta 0:00:00
2025-10-21 00:11:01.900170 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-21 00:11:04.537697 | 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-10-21 00:11:04.554060 | controller |
2025-10-21 00:11:04.747636 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-21 00:11:04.747684 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-21 00:11:05.246651 | controller | ok: Runtime: 0:00:04.675412
2025-10-21 00:11:05.272022 | 
2025-10-21 00:11:05.272220 | TASK [Update pip]
2025-10-21 00:11:06.372864 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-21 00:11:06.647834 | controller | Collecting pip
2025-10-21 00:11:06.761379 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-21 00:11:06.929652 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.7 MB/s eta 0:00:00
2025-10-21 00:11:07.088825 | controller | Installing collected packages: pip
2025-10-21 00:11:07.090112 | controller |   Attempting uninstall: pip
2025-10-21 00:11:07.096268 | controller |     Found existing installation: pip 22.2.2
2025-10-21 00:11:07.387475 | controller |     Uninstalling pip-22.2.2:
2025-10-21 00:11:07.417320 | controller |       Successfully uninstalled pip-22.2.2
2025-10-21 00:11:09.162722 | controller | Successfully installed pip-25.2
2025-10-21 00:11:09.431875 | controller | ok: Runtime: 0:00:03.585884
2025-10-21 00:11:09.439124 | 
2025-10-21 00:11:09.439216 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-21 00:11:10.016983 | controller | changed
2025-10-21 00:11:10.024256 | 
2025-10-21 00:11:10.024350 | TASK [Install ansible into virtualenv]
2025-10-21 00:11:11.173938 | controller | Processing ./src/github.com/ansible/ansible
2025-10-21 00:11:11.180233 | controller |   Installing build dependencies: started
2025-10-21 00:11:13.155542 | controller |   Installing build dependencies: finished with status 'done'
2025-10-21 00:11:13.156651 | controller |   Getting requirements to build wheel: started
2025-10-21 00:11:14.746380 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-21 00:11:14.747795 | controller |   Preparing metadata (pyproject.toml): started
2025-10-21 00:11:15.689390 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-21 00:11:15.691624 | 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-21 00:11:15.696507 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-21 00:11:16.202089 | controller | ERROR
2025-10-21 00:11:16.202253 | controller | {
2025-10-21 00:11:16.202281 | controller |   "delta": "0:00:05.384369",
2025-10-21 00:11:16.202300 | controller |   "end": "2025-10-21 00:11:15.850723",
2025-10-21 00:11:16.202317 | controller |   "msg": "non-zero return code",
2025-10-21 00:11:16.202339 | controller |   "rc": 1,
2025-10-21 00:11:16.202357 | controller |   "start": "2025-10-21 00:11:10.466354"
2025-10-21 00:11:16.202372 | controller | }
failure
2025-10-21 00:11:16.204710 | 
2025-10-21 00:11:16.204766 | PLAY RECAP
2025-10-21 00:11:16.204840 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-21 00:11:16.204873 | 
2025-10-21 00:11:16.353264 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-21 00:11:16.354227 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-21 00:11:17.111460 | 
2025-10-21 00:11:17.111601 | PLAY [all]
2025-10-21 00:11:17.142919 | 
2025-10-21 00:11:17.143065 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-21 00:11:17.988499 | controller | changed: non-zero return code
2025-10-21 00:11:17.996505 | 
2025-10-21 00:11:17.996619 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-21 00:11:18.012436 | controller | skipping: Conditional result was False
2025-10-21 00:11:18.020185 | 
2025-10-21 00:11:18.020298 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-21 00:11:18.068456 | 
2025-10-21 00:11:18.068642 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-21 00:11:18.105487 | 
2025-10-21 00:11:18.105732 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-21 00:11:18.121825 | controller | skipping: Conditional result was False
2025-10-21 00:11:18.133373 | 
2025-10-21 00:11:18.133514 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-21 00:11:18.170440 | 
2025-10-21 00:11:18.170609 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-21 00:11:18.185365 | controller | skipping: Conditional result was False
2025-10-21 00:11:18.193140 | 
2025-10-21 00:11:18.193236 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-21 00:11:18.209048 | controller | skipping: Conditional result was False
2025-10-21 00:11:18.217253 | 
2025-10-21 00:11:18.217371 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-21 00:11:18.241349 | controller | skipping: Conditional result was False
2025-10-21 00:11:18.280861 | 
2025-10-21 00:11:18.280954 | PLAY RECAP
2025-10-21 00:11:18.280998 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-21 00:11:18.281020 | 
2025-10-21 00:11:18.391884 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-21 00:11:18.392752 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-21 00:11:19.015971 | 
2025-10-21 00:11:19.016101 | PLAY [all:!appliance*]
2025-10-21 00:11:19.057280 | 
2025-10-21 00:11:19.057410 | TASK [unregister the node]
2025-10-21 00:11:19.203337 | controller | skipping: Conditional result was False
2025-10-21 00:11:19.209257 | 
2025-10-21 00:11:19.209342 | TASK [include_role : fetch-output]
2025-10-21 00:11:19.249876 | controller | ok
2025-10-21 00:11:19.344147 | 
2025-10-21 00:11:19.344327 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-21 00:11:19.422927 | controller | skipping: Conditional result was False
2025-10-21 00:11:19.429933 | 
2025-10-21 00:11:19.430042 | TASK [fetch-output : Set log path for single node]
2025-10-21 00:11:19.469145 | controller | ok
2025-10-21 00:11:19.474391 | 
2025-10-21 00:11:19.474463 | LOOP [fetch-output : Ensure local output dirs]
2025-10-21 00:11:20.327025 | controller -> localhost | ok: "/var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/logs"
2025-10-21 00:11:20.631015 | controller -> localhost | changed: "/var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/artifacts"
2025-10-21 00:11:21.002252 | controller -> localhost | changed: "/var/lib/zuul/builds/15080781a79f4813afe5a750711ee202/work/docs"
2025-10-21 00:11:21.017882 | 
2025-10-21 00:11:21.018017 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-21 00:11:22.407180 | controller | changed:
2025-10-21 00:11:22.407396 | controller | .d..t...... ./
2025-10-21 00:11:22.407426 | controller | cd+++++++++ controller/
2025-10-21 00:11:22.407472 | controller | changed: All items complete
2025-10-21 00:11:22.407494 | 
2025-10-21 00:11:23.665154 | controller | changed: .d..t...... ./
2025-10-21 00:11:24.790122 | controller | changed: .d..t...... ./
2025-10-21 00:11:24.845995 | 
2025-10-21 00:11:24.846180 | TASK [include_role : fetch-output-openshift]
2025-10-21 00:11:24.872824 | controller | skipping: Conditional result was False
2025-10-21 00:11:24.882010 | 
2025-10-21 00:11:24.882171 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-21 00:11:24.919449 | controller | skipping: Conditional result was False
2025-10-21 00:11:24.932043 | controller | skipping: Conditional result was False
2025-10-21 00:11:24.979442 | 
2025-10-21 00:11:24.979583 | PLAY [localhost]
2025-10-21 00:11:24.997163 | 
2025-10-21 00:11:24.997282 | TASK [Run Zuul manifest role]
2025-10-21 00:11:25.020997 | localhost | ok
2025-10-21 00:11:25.077972 | 
2025-10-21 00:11:25.078130 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-21 00:11:25.620856 | localhost | changed
2025-10-21 00:11:25.629959 | 
2025-10-21 00:11:25.630119 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-21 00:11:25.675837 | localhost | ok
2025-10-21 00:11:25.691952 | 
2025-10-21 00:11:25.692107 | TASK [Set zuul-log-path fact]
2025-10-21 00:11:25.727573 | localhost | ok
2025-10-21 00:11:25.759362 | 
2025-10-21 00:11:25.759533 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-21 00:11:25.813932 | localhost | ok
2025-10-21 00:11:25.835837 | 
2025-10-21 00:11:25.835984 | LOOP [Run upload-logs-swift role]
2025-10-21 00:11:25.885910 | localhost | Output suppressed because no_log was given
2025-10-21 00:11:25.947842 | 
2025-10-21 00:11:25.947995 | TASK [Set zuul-log-path fact]
2025-10-21 00:11:25.973354 | localhost | skipping: Conditional result was False
2025-10-21 00:11:25.982927 | 
2025-10-21 00:11:25.983070 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-21 00:11:26.619779 | localhost -> localhost | ok: Runtime: 0:00:00.009020
2025-10-21 00:11:26.628197 | 
2025-10-21 00:11:26.628335 | TASK [upload-logs-swift : Upload logs to swift]