2025-10-20 00:12:11.339042 | Job console starting...
2025-10-20 00:12:11.351219 | Updating repositories
2025-10-20 00:12:11.467796 | Preparing job workspace
2025-10-20 00:12:15.114043 | Running Ansible setup...
2025-10-20 00:12:20.840042 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-20 00:12:21.527964 | 
2025-10-20 00:12:21.528110 | PLAY [localhost]
2025-10-20 00:12:21.537579 | 
2025-10-20 00:12:21.537692 | TASK [Gathering Facts]
2025-10-20 00:12:22.583804 | localhost | ok
2025-10-20 00:12:22.597779 | 
2025-10-20 00:12:22.597917 | TASK [Setup log path fact]
2025-10-20 00:12:22.617566 | localhost | ok
2025-10-20 00:12:22.635081 | 
2025-10-20 00:12:22.635240 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-20 00:12:22.665791 | localhost | ok
2025-10-20 00:12:22.676482 | 
2025-10-20 00:12:22.676605 | TASK [emit-job-header : Print job information]
2025-10-20 00:12:22.707505 | # Job Information
2025-10-20 00:12:22.707697 | Ansible Version: 2.15.12
2025-10-20 00:12:22.707767 | Job: ansible-test-sanity-docker-devel
2025-10-20 00:12:22.707803 | Pipeline: periodic
2025-10-20 00:12:22.707830 | Executor: ze03.softwarefactory-project.io
2025-10-20 00:12:22.707856 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-20 00:12:22.707885 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/712/ansible/712943b764794211843712afe41cbd05/
2025-10-20 00:12:22.707913 | Event ID: 328e9597672940b996d379e8913dc261
2025-10-20 00:12:22.713005 | 
2025-10-20 00:12:22.713098 | LOOP [emit-job-header : Print node information]
2025-10-20 00:12:22.814832 | localhost | ok:
2025-10-20 00:12:22.815014 | localhost | # Node Information
2025-10-20 00:12:22.815052 | localhost | Inventory Hostname: controller
2025-10-20 00:12:22.815082 | localhost | Hostname: ip-172-16-45-28
2025-10-20 00:12:22.815110 | localhost | Username: zuul-worker
2025-10-20 00:12:22.815141 | localhost | Distro: Fedora 37
2025-10-20 00:12:22.815169 | localhost | Provider: ansible-us-east-2
2025-10-20 00:12:22.815201 | localhost | Region: us-east-2
2025-10-20 00:12:22.815228 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-20 00:12:22.815254 | localhost | Product Name: t3.small
2025-10-20 00:12:22.815281 | localhost | Interface IP: 13.58.18.56
2025-10-20 00:12:22.829279 | 
2025-10-20 00:12:22.829397 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-20 00:12:23.201259 | localhost -> localhost | changed
2025-10-20 00:12:23.208936 | 
2025-10-20 00:12:23.209081 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-20 00:12:24.080681 | localhost -> localhost | changed
2025-10-20 00:12:24.100687 | 
2025-10-20 00:12:24.100813 | PLAY [all:!appliance*]
2025-10-20 00:12:24.118061 | 
2025-10-20 00:12:24.118172 | TASK [include_role : start-zuul-console]
2025-10-20 00:12:24.137222 | controller | ok
2025-10-20 00:12:24.151086 | 
2025-10-20 00:12:24.151198 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-20 00:12:24.822233 | controller | ok
2025-10-20 00:12:24.833526 | 
2025-10-20 00:12:24.833639 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-20 00:12:26.260527 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-20 00:12:26.277393 | 
2025-10-20 00:12:26.277583 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-20 00:12:26.447473 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.456598 | 
2025-10-20 00:12:26.456712 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-20 00:12:26.492246 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.506923 | 
2025-10-20 00:12:26.507122 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-20 00:12:26.544475 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.558562 | 
2025-10-20 00:12:26.558771 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-20 00:12:26.595083 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.606978 | 
2025-10-20 00:12:26.607101 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-20 00:12:26.642905 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.652540 | 
2025-10-20 00:12:26.652700 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-20 00:12:26.678719 | controller | skipping: Conditional result was False
2025-10-20 00:12:26.695416 | 
2025-10-20 00:12:26.695538 | TASK [Disable Fedora Modular]
2025-10-20 00:12:27.407431 | controller | changed
2025-10-20 00:12:27.415128 | 
2025-10-20 00:12:27.415255 | TASK [Enable EPEL]
2025-10-20 00:12:27.441105 | controller | skipping: Conditional result was False
2025-10-20 00:12:27.455343 | 
2025-10-20 00:12:27.455493 | TASK [Register the RHEL node]
2025-10-20 00:12:27.623359 | 
2025-10-20 00:12:27.623667 | TASK [Show the subscription-manager status]
2025-10-20 00:12:27.801125 | controller | skipping: Conditional result was False
2025-10-20 00:12:27.841805 | 
2025-10-20 00:12:27.841941 | TASK [Enable EPEL on RHEL]
2025-10-20 00:12:27.995167 | controller | skipping: Conditional result was False
2025-10-20 00:12:28.007424 | 
2025-10-20 00:12:28.007568 | TASK [Install git and tox]
2025-10-20 00:14:02.941900 | controller | changed
2025-10-20 00:14:02.950053 | 
2025-10-20 00:14:02.950188 | TASK [include_role : prepare-workspace]
2025-10-20 00:14:02.984624 | controller | ok
2025-10-20 00:14:03.015942 | 
2025-10-20 00:14:03.016116 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-20 00:14:03.902137 | controller | ok
2025-10-20 00:14:03.915129 | 
2025-10-20 00:14:03.915327 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-20 00:14:16.465812 | controller | Output suppressed because no_log was given
2025-10-20 00:14:16.476617 | 
2025-10-20 00:14:16.476719 | TASK [include_role : prepare-workspace-openshift]
2025-10-20 00:14:16.500826 | controller | skipping: Conditional result was False
2025-10-20 00:14:16.527025 | 
2025-10-20 00:14:16.527141 | PLAY [all:!appliance]
2025-10-20 00:14:16.544294 | 
2025-10-20 00:14:16.544420 | TASK [Run add-build-sshkey role (RSA)]
2025-10-20 00:14:16.575073 | controller | ok
2025-10-20 00:14:16.589367 | 
2025-10-20 00:14:16.589443 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-20 00:14:16.860665 | controller -> localhost | ok
2025-10-20 00:14:16.900683 | 
2025-10-20 00:14:16.900852 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-20 00:14:16.932977 | controller | ok
2025-10-20 00:14:16.947940 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-20 00:14:16.954058 | 
2025-10-20 00:14:16.954144 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-20 00:14:17.586543 | controller -> localhost | Generating public/private rsa key pair.
2025-10-20 00:14:17.587032 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_rsa.
2025-10-20 00:14:17.587123 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_rsa.pub.
2025-10-20 00:14:17.587193 | controller -> localhost | The key fingerprint is:
2025-10-20 00:14:17.587258 | controller -> localhost | SHA256:uWw0AOuDqrt/YJDtwtNUQ3+/lhaWqvaV/RuvzL1OJQM zuul-build-sshkey
2025-10-20 00:14:17.587319 | controller -> localhost | The key's randomart image is:
2025-10-20 00:14:17.587376 | controller -> localhost | +---[RSA 2048]----+
2025-10-20 00:14:17.587436 | controller -> localhost | |    o.           |
2025-10-20 00:14:17.587497 | controller -> localhost | |     =.          |
2025-10-20 00:14:17.587556 | controller -> localhost | | o  o o. .  E    |
2025-10-20 00:14:17.587615 | controller -> localhost | |o .+   .... ..   |
2025-10-20 00:14:17.587674 | controller -> localhost | |.o+ o   S  =  o .|
2025-10-20 00:14:17.587797 | controller -> localhost | |.++. . o oo *  o.|
2025-10-20 00:14:17.587891 | controller -> localhost | |.o..    +. B . o |
2025-10-20 00:14:17.587961 | controller -> localhost | |.   .  o. +  oo.o|
2025-10-20 00:14:17.588056 | controller -> localhost | |++..  ....    =*=|
2025-10-20 00:14:17.588126 | controller -> localhost | +----[SHA256]-----+
2025-10-20 00:14:17.588257 | controller -> localhost | ok: Runtime: 0:00:00.175631
2025-10-20 00:14:17.609419 | 
2025-10-20 00:14:17.609571 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-20 00:14:17.656484 | controller | ok
2025-10-20 00:14:17.679201 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-20 00:14:17.693326 | 
2025-10-20 00:14:17.693479 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-20 00:14:17.720341 | controller | skipping: Conditional result was False
2025-10-20 00:14:17.729425 | 
2025-10-20 00:14:17.729518 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-20 00:14:18.446408 | controller | changed
2025-10-20 00:14:18.460083 | 
2025-10-20 00:14:18.460247 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-20 00:14:18.908063 | controller | ok
2025-10-20 00:14:18.940075 | 
2025-10-20 00:14:18.940212 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-20 00:14:20.472345 | controller | changed
2025-10-20 00:14:20.479998 | 
2025-10-20 00:14:20.480116 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-20 00:14:21.984894 | controller | changed
2025-10-20 00:14:21.998359 | 
2025-10-20 00:14:21.998530 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-20 00:14:22.027050 | controller | skipping: Conditional result was False
2025-10-20 00:14:22.040802 | 
2025-10-20 00:14:22.040951 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-20 00:14:22.458615 | controller -> localhost | changed
2025-10-20 00:14:22.472041 | 
2025-10-20 00:14:22.472168 | TASK [add-build-sshkey : Add back temp key]
2025-10-20 00:14:22.734644 | controller -> localhost | Identity added: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_rsa (zuul-build-sshkey)
2025-10-20 00:14:22.735152 | controller -> localhost | ok: Runtime: 0:00:00.013734
2025-10-20 00:14:22.750236 | 
2025-10-20 00:14:22.750409 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-20 00:14:23.370628 | controller | ok
2025-10-20 00:14:23.378290 | 
2025-10-20 00:14:23.378408 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-20 00:14:23.424668 | controller | skipping: Conditional result was False
2025-10-20 00:14:23.450160 | 
2025-10-20 00:14:23.450336 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-20 00:14:23.482854 | controller | ok
2025-10-20 00:14:23.504288 | 
2025-10-20 00:14:23.504440 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-20 00:14:23.796374 | controller -> localhost | ok
2025-10-20 00:14:23.811556 | 
2025-10-20 00:14:23.811785 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-20 00:14:23.855497 | controller | ok
2025-10-20 00:14:23.879518 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-20 00:14:23.889061 | 
2025-10-20 00:14:23.889201 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-20 00:14:24.213178 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-20 00:14:24.213552 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_ecdsa.
2025-10-20 00:14:24.213618 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_ecdsa.pub.
2025-10-20 00:14:24.213683 | controller -> localhost | The key fingerprint is:
2025-10-20 00:14:24.213762 | controller -> localhost | SHA256:veSbvIxJHtj2R1wWP6PiA6OW0RfSuBDQNrpKVHOIMMk zuul-build-sshkey
2025-10-20 00:14:24.213817 | controller -> localhost | The key's randomart image is:
2025-10-20 00:14:24.213862 | controller -> localhost | +---[ECDSA 521]---+
2025-10-20 00:14:24.213904 | controller -> localhost | |.oo ..+          |
2025-10-20 00:14:24.213945 | controller -> localhost | | E.. + *      .  |
2025-10-20 00:14:24.213985 | controller -> localhost | |    . = o o    o |
2025-10-20 00:14:24.214024 | controller -> localhost | |   . . . + o  oo.|
2025-10-20 00:14:24.214064 | controller -> localhost | |  .   . S =..o. o|
2025-10-20 00:14:24.214103 | controller -> localhost | |   . . + B +o.   |
2025-10-20 00:14:24.214143 | controller -> localhost | |  . . . O B..    |
2025-10-20 00:14:24.214182 | controller -> localhost | |   .   B B =.    |
2025-10-20 00:14:24.214223 | controller -> localhost | |      . + Bo.    |
2025-10-20 00:14:24.214264 | controller -> localhost | +----[SHA256]-----+
2025-10-20 00:14:24.214380 | controller -> localhost | ok: Runtime: 0:00:00.015930
2025-10-20 00:14:24.230184 | 
2025-10-20 00:14:24.230340 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-20 00:14:24.271050 | controller | ok
2025-10-20 00:14:24.289572 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-20 00:14:24.304289 | 
2025-10-20 00:14:24.304414 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-20 00:14:24.320501 | controller | skipping: Conditional result was False
2025-10-20 00:14:24.329359 | 
2025-10-20 00:14:24.329455 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-20 00:14:24.770041 | controller | changed
2025-10-20 00:14:24.775912 | 
2025-10-20 00:14:24.775985 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-20 00:14:25.197908 | controller | ok
2025-10-20 00:14:25.214812 | 
2025-10-20 00:14:25.214975 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-20 00:14:26.686651 | controller | changed
2025-10-20 00:14:26.701257 | 
2025-10-20 00:14:26.701432 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-20 00:14:28.258400 | controller | changed
2025-10-20 00:14:28.266151 | 
2025-10-20 00:14:28.266271 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-20 00:14:28.301429 | controller | skipping: Conditional result was False
2025-10-20 00:14:28.308810 | 
2025-10-20 00:14:28.308897 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-20 00:14:28.639263 | controller -> localhost | changed
2025-10-20 00:14:28.651529 | 
2025-10-20 00:14:28.651635 | TASK [add-build-sshkey : Add back temp key]
2025-10-20 00:14:28.931159 | controller -> localhost | Identity added: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/712943b764794211843712afe41cbd05_id_ecdsa (zuul-build-sshkey)
2025-10-20 00:14:28.931372 | controller -> localhost | ok: Runtime: 0:00:00.007813
2025-10-20 00:14:28.939880 | 
2025-10-20 00:14:28.939962 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-20 00:14:29.516544 | controller | ok
2025-10-20 00:14:29.524530 | 
2025-10-20 00:14:29.524660 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-20 00:14:29.550453 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.571886 | 
2025-10-20 00:14:29.572072 | TASK [include_role : remove-zuul-sshkey]
2025-10-20 00:14:29.598701 | controller | skipping: Conditional result was False
2025-10-20 00:14:29.608674 | 
2025-10-20 00:14:29.608782 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-20 00:14:30.147216 | controller | ok: "logs"
2025-10-20 00:14:30.147397 | controller | ok: All items complete
2025-10-20 00:14:30.147426 | 
2025-10-20 00:14:30.514350 | controller | ok: "artifacts"
2025-10-20 00:14:30.836146 | controller | ok: "docs"
2025-10-20 00:14:30.845599 | 
2025-10-20 00:14:30.845744 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-20 00:14:31.235092 | controller | changed: "logs"
2025-10-20 00:14:31.576233 | controller | changed: "artifacts"
2025-10-20 00:14:31.886192 | controller | changed: "docs"
2025-10-20 00:14:31.945015 | 
2025-10-20 00:14:31.945146 | PLAY RECAP
2025-10-20 00:14:31.945209 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-20 00:14:31.945246 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-20 00:14:31.945272 | 
2025-10-20 00:14:32.065179 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-20 00:14:32.067098 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-20 00:14:32.676327 | 
2025-10-20 00:14:32.676436 | PLAY [all]
2025-10-20 00:14:32.697522 | 
2025-10-20 00:14:32.697622 | TASK [Install binary dependencies]
2025-10-20 00:14:32.749896 | controller | ok
2025-10-20 00:14:32.776719 | 
2025-10-20 00:14:32.776892 | TASK [bindep : Include find tasks]
2025-10-20 00:14:32.806620 | controller | ok
2025-10-20 00:14:32.814244 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-20 00:14:32.820396 | 
2025-10-20 00:14:32.820459 | TASK [bindep : Look for bindep.txt]
2025-10-20 00:14:33.369847 | controller | ok
2025-10-20 00:14:33.383692 | 
2025-10-20 00:14:33.383919 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:33.411107 | controller | skipping: Conditional result was False
2025-10-20 00:14:33.420190 | 
2025-10-20 00:14:33.420347 | TASK [bindep : Look for other-requirements.txt]
2025-10-20 00:14:33.743400 | controller | ok
2025-10-20 00:14:33.755409 | 
2025-10-20 00:14:33.755561 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:33.792920 | controller | skipping: Conditional result was False
2025-10-20 00:14:33.805839 | 
2025-10-20 00:14:33.805991 | TASK [bindep : Look for bindep fallback file]
2025-10-20 00:14:33.843166 | controller | skipping: Conditional result was False
2025-10-20 00:14:33.856342 | 
2025-10-20 00:14:33.856496 | TASK [bindep : Define bindep_file fact]
2025-10-20 00:14:33.893786 | controller | skipping: Conditional result was False
2025-10-20 00:14:33.909442 | 
2025-10-20 00:14:33.909664 | TASK [bindep : Include bindep tasks]
2025-10-20 00:14:33.948147 | controller | skipping: Conditional result was False
2025-10-20 00:14:33.965751 | 
2025-10-20 00:14:33.965956 | TASK [bindep : Include install tasks]
2025-10-20 00:14:34.016601 | controller | skipping: Conditional result was False
2025-10-20 00:14:34.030386 | 
2025-10-20 00:14:34.030610 | LOOP [bindep : Include package tasks]
2025-10-20 00:14:34.103519 | 
2025-10-20 00:14:34.103766 | TASK [Run test-setup role]
2025-10-20 00:14:34.126410 | controller | ok
2025-10-20 00:14:34.159123 | 
2025-10-20 00:14:34.159250 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-20 00:14:34.541858 | controller | ok
2025-10-20 00:14:34.554902 | 
2025-10-20 00:14:34.555048 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-20 00:14:34.710802 | controller | skipping: Conditional result was False
2025-10-20 00:14:34.745478 | 
2025-10-20 00:14:34.745603 | PLAY RECAP
2025-10-20 00:14:34.745659 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-20 00:14:34.745752 | 
2025-10-20 00:14:34.844381 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-20 00:14:34.845476 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-20 00:14:35.443076 | 
2025-10-20 00:14:35.443228 | PLAY [controller]
2025-10-20 00:14:35.464157 | 
2025-10-20 00:14:35.464269 | TASK [Create the /root directory]
2025-10-20 00:14:36.223073 | controller | ok
2025-10-20 00:14:36.236764 | 
2025-10-20 00:14:36.236946 | TASK [Install glibc-langpack-en]
2025-10-20 00:14:44.578151 | controller | ok: Nothing to do
2025-10-20 00:14:44.591846 | 
2025-10-20 00:14:44.591996 | TASK [Ensure controller directory exists]
2025-10-20 00:14:45.026476 | controller | changed
2025-10-20 00:14:45.034967 | 
2025-10-20 00:14:45.035083 | TASK [Install container runtime]
2025-10-20 00:14:45.094112 | controller | ok
2025-10-20 00:14:45.152258 | 
2025-10-20 00:14:45.152379 | LOOP [ensure-podman : Find distribution installation]
2025-10-20 00:14:45.183440 | controller | ok: "/var/lib/zuul/builds/712943b764794211843712afe41cbd05/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-20 00:14:45.193293 | controller | included: /var/lib/zuul/builds/712943b764794211843712afe41cbd05/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-20 00:14:45.199669 | 
2025-10-20 00:14:45.199751 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-20 00:16:04.593090 | controller | changed
2025-10-20 00:16:04.603879 | 
2025-10-20 00:16:04.604020 | TASK [ensure-podman : Fetch podman version]
2025-10-20 00:16:05.351949 | controller | Client:       Podman Engine
2025-10-20 00:16:05.352054 | controller | Version:      4.6.2
2025-10-20 00:16:05.352097 | controller | API Version:  4.6.2
2025-10-20 00:16:05.352137 | controller | Go Version:   go1.19.12
2025-10-20 00:16:05.352193 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-20 00:16:05.352236 | controller | OS/Arch:      linux/amd64
2025-10-20 00:16:05.762364 | controller | ok: Runtime: 0:00:00.225814
2025-10-20 00:16:05.778668 | 
2025-10-20 00:16:05.778942 | TASK [ensure-podman : Print podman version installed]
2025-10-20 00:16:05.811195 | Podman version: Client:       Podman Engine
2025-10-20 00:16:05.811458 | Version:      4.6.2
2025-10-20 00:16:05.811521 | API Version:  4.6.2
2025-10-20 00:16:05.811568 | Go Version:   go1.19.12
2025-10-20 00:16:05.811611 | Built:        Mon Aug 28 19:38:31 2023
2025-10-20 00:16:05.811655 | OS/Arch:      linux/amd64
2025-10-20 00:16:05.824154 | 
2025-10-20 00:16:05.824324 | TASK [ensure-podman : Validate podman engine]
2025-10-20 00:16:05.975645 | controller | skipping: Conditional result was False
2025-10-20 00:16:05.989392 | 
2025-10-20 00:16:05.989588 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-20 00:16:06.006616 | controller | skipping: Conditional result was False
2025-10-20 00:16:06.033167 | 
2025-10-20 00:16:06.033343 | TASK [Ensure python3.8 is present]
2025-10-20 00:16:06.048692 | controller | skipping: Conditional result was False
2025-10-20 00:16:06.058646 | 
2025-10-20 00:16:06.058834 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-20 00:16:06.082626 | controller | ok
2025-10-20 00:16:06.111695 | 
2025-10-20 00:16:06.111881 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-20 00:16:09.882928 | controller | ok: Nothing to do
2025-10-20 00:16:09.896409 | 
2025-10-20 00:16:09.896590 | TASK [our-ensure-python : Also install python3-devel]
2025-10-20 00:16:22.898534 | controller | changed
2025-10-20 00:16:22.924961 | 
2025-10-20 00:16:22.925140 | TASK [Run ensure-virtualenv role]
2025-10-20 00:16:22.956871 | controller | ok
2025-10-20 00:16:23.001310 | 
2025-10-20 00:16:23.001455 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-20 00:16:23.378509 | controller | /usr/bin/virtualenv
2025-10-20 00:16:23.658305 | controller | ok: Runtime: 0:00:00.004396
2025-10-20 00:16:23.667957 | 
2025-10-20 00:16:23.668086 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-20 00:16:23.692442 | controller | skipping: Conditional result was False
2025-10-20 00:16:23.692754 | controller | ok: All items complete
2025-10-20 00:16:23.692808 | 
2025-10-20 00:16:23.715777 | 
2025-10-20 00:16:23.715955 | TASK [Find the full path of the Python interpreter]
2025-10-20 00:16:24.140348 | controller | /usr/bin/python3
2025-10-20 00:16:24.368267 | controller | ok
2025-10-20 00:16:24.375959 | 
2025-10-20 00:16:24.376086 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-20 00:16:25.790195 | controller | created virtual environment CPython3.11.0.final.0-64 in 776ms
2025-10-20 00:16:25.836473 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-20 00:16:25.836592 | 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-20 00:16:25.836613 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-20 00:16:25.836635 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-20 00:16:26.039349 | controller | changed
2025-10-20 00:16:26.052577 | 
2025-10-20 00:16:26.052717 | TASK [Set selinux package]
2025-10-20 00:16:26.081898 | controller | ok
2025-10-20 00:16:26.096783 | 
2025-10-20 00:16:26.096928 | TASK [Set selinux package (Fedora)]
2025-10-20 00:16:26.147125 | controller | ok
2025-10-20 00:16:26.160230 | 
2025-10-20 00:16:26.160436 | TASK [Install selinux into virtualenv]
2025-10-20 00:16:28.790432 | controller | Collecting selinux-please-lie-to-me
2025-10-20 00:16:28.877828 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-20 00:16:29.404681 | controller | Collecting setuptools<50.0.0
2025-10-20 00:16:29.426415 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-20 00:16:29.536645 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.9 MB/s eta 0:00:00
2025-10-20 00:16:29.690999 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-20 00:16:29.691426 | controller |   Attempting uninstall: setuptools
2025-10-20 00:16:29.696309 | controller |     Found existing installation: setuptools 62.6.0
2025-10-20 00:16:29.808419 | controller |     Uninstalling setuptools-62.6.0:
2025-10-20 00:16:29.823903 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-20 00:16:30.606668 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-20 00:16:30.815262 | controller |
2025-10-20 00:16:31.030745 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-20 00:16:31.030789 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-20 00:16:31.370123 | controller | ok: Runtime: 0:00:04.381956
2025-10-20 00:16:31.382632 | 
2025-10-20 00:16:31.382853 | TASK [Install pytest-forked into virtualenv]
2025-10-20 00:16:32.636701 | controller | Collecting pytest-forked
2025-10-20 00:16:32.724795 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-20 00:16:32.786283 | controller | Collecting py
2025-10-20 00:16:32.802274 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-20 00:16:32.835460 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.6 MB/s eta 0:00:00
2025-10-20 00:16:33.012428 | controller | Collecting pytest>=3.10
2025-10-20 00:16:33.044976 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-20 00:16:33.111384 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.7 MB/s eta 0:00:00
2025-10-20 00:16:33.167846 | controller | Collecting iniconfig>=1
2025-10-20 00:16:33.204543 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-20 00:16:33.267631 | controller | Collecting packaging>=20
2025-10-20 00:16:33.283150 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-20 00:16:33.294960 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.0 MB/s eta 0:00:00
2025-10-20 00:16:33.339525 | controller | Collecting pluggy<2,>=1.5
2025-10-20 00:16:33.353401 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-20 00:16:33.488602 | controller | Collecting pygments>=2.7.2
2025-10-20 00:16:33.549200 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-20 00:16:33.666298 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-10-20 00:16:33.798641 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-20 00:16:36.105151 | 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-20 00:16:36.121102 | controller |
2025-10-20 00:16:36.302378 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-20 00:16:36.302430 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-20 00:16:36.559624 | controller | ok: Runtime: 0:00:04.414819
2025-10-20 00:16:36.572406 | 
2025-10-20 00:16:36.572571 | TASK [Update pip]
2025-10-20 00:16:37.823191 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-20 00:16:38.117429 | controller | Collecting pip
2025-10-20 00:16:38.216184 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-20 00:16:38.380353 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.9 MB/s eta 0:00:00
2025-10-20 00:16:38.548076 | controller | Installing collected packages: pip
2025-10-20 00:16:38.549503 | controller |   Attempting uninstall: pip
2025-10-20 00:16:38.554475 | controller |     Found existing installation: pip 22.2.2
2025-10-20 00:16:38.835545 | controller |     Uninstalling pip-22.2.2:
2025-10-20 00:16:38.865383 | controller |       Successfully uninstalled pip-22.2.2
2025-10-20 00:16:40.598684 | controller | Successfully installed pip-25.2
2025-10-20 00:16:41.247378 | controller | ok: Runtime: 0:00:03.643472
2025-10-20 00:16:41.256801 | 
2025-10-20 00:16:41.256898 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-20 00:16:41.829405 | controller | changed
2025-10-20 00:16:41.838062 | 
2025-10-20 00:16:41.838169 | TASK [Install ansible into virtualenv]
2025-10-20 00:16:42.928501 | controller | Processing ./src/github.com/ansible/ansible
2025-10-20 00:16:42.935088 | controller |   Installing build dependencies: started
2025-10-20 00:16:44.834640 | controller |   Installing build dependencies: finished with status 'done'
2025-10-20 00:16:44.835880 | controller |   Getting requirements to build wheel: started
2025-10-20 00:16:46.366642 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-20 00:16:46.368451 | controller |   Preparing metadata (pyproject.toml): started
2025-10-20 00:16:47.292641 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-20 00:16:47.297702 | 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-20 00:16:47.302557 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-20 00:16:47.988974 | controller | ERROR
2025-10-20 00:16:47.989180 | controller | {
2025-10-20 00:16:47.989227 | controller |   "delta": "0:00:05.195214",
2025-10-20 00:16:47.989255 | controller |   "end": "2025-10-20 00:16:47.452759",
2025-10-20 00:16:47.989275 | controller |   "msg": "non-zero return code",
2025-10-20 00:16:47.989303 | controller |   "rc": 1,
2025-10-20 00:16:47.989320 | controller |   "start": "2025-10-20 00:16:42.257545"
2025-10-20 00:16:47.989336 | controller | }
failure
2025-10-20 00:16:47.991068 | 
2025-10-20 00:16:47.991117 | PLAY RECAP
2025-10-20 00:16:47.991161 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-20 00:16:47.991183 | 
2025-10-20 00:16:48.117542 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-20 00:16:48.118772 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-20 00:16:48.792952 | 
2025-10-20 00:16:48.793114 | PLAY [all]
2025-10-20 00:16:48.818401 | 
2025-10-20 00:16:48.818549 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-20 00:16:49.587495 | controller | changed: non-zero return code
2025-10-20 00:16:49.598822 | 
2025-10-20 00:16:49.599061 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-20 00:16:49.627626 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.635970 | 
2025-10-20 00:16:49.636110 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-20 00:16:49.671491 | 
2025-10-20 00:16:49.671696 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-20 00:16:49.708081 | 
2025-10-20 00:16:49.708413 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-20 00:16:49.734858 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.745202 | 
2025-10-20 00:16:49.745339 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-20 00:16:49.773013 | 
2025-10-20 00:16:49.773207 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-20 00:16:49.788882 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.797535 | 
2025-10-20 00:16:49.797683 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-20 00:16:49.818715 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.825218 | 
2025-10-20 00:16:49.825351 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-20 00:16:49.839891 | controller | skipping: Conditional result was False
2025-10-20 00:16:49.867677 | 
2025-10-20 00:16:49.867816 | PLAY RECAP
2025-10-20 00:16:49.867878 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-20 00:16:49.867943 | 
2025-10-20 00:16:49.995950 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-20 00:16:49.996866 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-20 00:16:50.602129 | 
2025-10-20 00:16:50.602276 | PLAY [all:!appliance*]
2025-10-20 00:16:50.624980 | 
2025-10-20 00:16:50.625127 | TASK [unregister the node]
2025-10-20 00:16:50.758592 | controller | skipping: Conditional result was False
2025-10-20 00:16:50.767652 | 
2025-10-20 00:16:50.767793 | TASK [include_role : fetch-output]
2025-10-20 00:16:50.822023 | controller | ok
2025-10-20 00:16:50.844097 | 
2025-10-20 00:16:50.844171 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-20 00:16:50.922159 | controller | skipping: Conditional result was False
2025-10-20 00:16:50.937720 | 
2025-10-20 00:16:50.938046 | TASK [fetch-output : Set log path for single node]
2025-10-20 00:16:50.988428 | controller | ok
2025-10-20 00:16:50.996516 | 
2025-10-20 00:16:50.996618 | LOOP [fetch-output : Ensure local output dirs]
2025-10-20 00:16:51.471968 | controller -> localhost | ok: "/var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/logs"
2025-10-20 00:16:51.718904 | controller -> localhost | changed: "/var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/artifacts"
2025-10-20 00:16:51.952038 | controller -> localhost | changed: "/var/lib/zuul/builds/712943b764794211843712afe41cbd05/work/docs"
2025-10-20 00:16:51.967004 | 
2025-10-20 00:16:51.967144 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-20 00:16:53.261782 | controller | changed:
2025-10-20 00:16:53.262159 | controller | .d..t...... ./
2025-10-20 00:16:53.262250 | controller | cd+++++++++ controller/
2025-10-20 00:16:53.262372 | controller | changed: All items complete
2025-10-20 00:16:53.262442 | 
2025-10-20 00:16:54.355610 | controller | changed: .d..t...... ./
2025-10-20 00:16:55.461090 | controller | changed: .d..t...... ./
2025-10-20 00:16:55.490227 | 
2025-10-20 00:16:55.490376 | TASK [include_role : fetch-output-openshift]
2025-10-20 00:16:55.517537 | controller | skipping: Conditional result was False
2025-10-20 00:16:55.531992 | 
2025-10-20 00:16:55.532168 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-20 00:16:55.570666 | controller | skipping: Conditional result was False
2025-10-20 00:16:55.580982 | controller | skipping: Conditional result was False
2025-10-20 00:16:55.617101 | 
2025-10-20 00:16:55.617363 | PLAY [localhost]
2025-10-20 00:16:55.630259 | 
2025-10-20 00:16:55.630362 | TASK [Run Zuul manifest role]
2025-10-20 00:16:55.648717 | localhost | ok
2025-10-20 00:16:55.663410 | 
2025-10-20 00:16:55.663536 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-20 00:16:56.052793 | localhost | changed
2025-10-20 00:16:56.057659 | 
2025-10-20 00:16:56.057749 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-20 00:16:56.086255 | localhost | ok
2025-10-20 00:16:56.094787 | 
2025-10-20 00:16:56.094880 | TASK [Set zuul-log-path fact]
2025-10-20 00:16:56.114037 | localhost | ok
2025-10-20 00:16:56.129002 | 
2025-10-20 00:16:56.129132 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-20 00:16:56.158170 | localhost | ok
2025-10-20 00:16:56.168129 | 
2025-10-20 00:16:56.168216 | LOOP [Run upload-logs-swift role]
2025-10-20 00:16:56.212543 | localhost | Output suppressed because no_log was given
2025-10-20 00:16:56.239793 | 
2025-10-20 00:16:56.239896 | TASK [Set zuul-log-path fact]
2025-10-20 00:16:56.274471 | localhost | skipping: Conditional result was False
2025-10-20 00:16:56.280331 | 
2025-10-20 00:16:56.280407 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-20 00:16:56.800360 | localhost -> localhost | ok: Runtime: 0:00:00.011119
2025-10-20 00:16:56.806299 | 
2025-10-20 00:16:56.806379 | TASK [upload-logs-swift : Upload logs to swift]