2025-10-30 00:12:24.763150 | Job console starting...
2025-10-30 00:12:24.774523 | Updating repositories
2025-10-30 00:12:24.945527 | Preparing job workspace
2025-10-30 00:12:29.509499 | Running Ansible setup...
2025-10-30 00:12:35.629392 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-30 00:12:36.256265 | 
2025-10-30 00:12:36.256413 | PLAY [localhost]
2025-10-30 00:12:36.274861 | 
2025-10-30 00:12:36.274996 | TASK [Gathering Facts]
2025-10-30 00:12:37.450714 | localhost | ok
2025-10-30 00:12:37.473292 | 
2025-10-30 00:12:37.473467 | TASK [Setup log path fact]
2025-10-30 00:12:37.495111 | localhost | ok
2025-10-30 00:12:37.525270 | 
2025-10-30 00:12:37.525650 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-30 00:12:37.569427 | localhost | ok
2025-10-30 00:12:37.583607 | 
2025-10-30 00:12:37.583796 | TASK [emit-job-header : Print job information]
2025-10-30 00:12:37.636416 | # Job Information
2025-10-30 00:12:37.636609 | Ansible Version: 2.15.12
2025-10-30 00:12:37.636661 | Job: ansible-test-sanity-docker-milestone
2025-10-30 00:12:37.636747 | Pipeline: periodic
2025-10-30 00:12:37.636781 | Executor: ze02.softwarefactory-project.io
2025-10-30 00:12:37.636814 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-30 00:12:37.636849 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/c0c/ansible/c0c6f1a3cb6b44ddb8a385b503872c7f/
2025-10-30 00:12:37.636881 | Event ID: 3d3b3e11113e4aa4883722e12166235f
2025-10-30 00:12:37.645743 | 
2025-10-30 00:12:37.645877 | LOOP [emit-job-header : Print node information]
2025-10-30 00:12:37.765545 | localhost | ok:
2025-10-30 00:12:37.765750 | localhost | # Node Information
2025-10-30 00:12:37.765779 | localhost | Inventory Hostname: controller
2025-10-30 00:12:37.765804 | localhost | Hostname: ip-172-16-24-160
2025-10-30 00:12:37.765823 | localhost | Username: zuul-worker
2025-10-30 00:12:37.765844 | localhost | Distro: Fedora 37
2025-10-30 00:12:37.765861 | localhost | Provider: ansible-us-east-2
2025-10-30 00:12:37.765878 | localhost | Region: us-east-2
2025-10-30 00:12:37.765895 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-30 00:12:37.765911 | localhost | Product Name: t3.small
2025-10-30 00:12:37.765928 | localhost | Interface IP: 3.17.144.91
2025-10-30 00:12:37.780308 | 
2025-10-30 00:12:37.780457 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-30 00:12:38.308359 | localhost -> localhost | changed
2025-10-30 00:12:38.314348 | 
2025-10-30 00:12:38.314453 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-30 00:12:39.777017 | localhost -> localhost | changed
2025-10-30 00:12:39.829695 | 
2025-10-30 00:12:39.829800 | PLAY [all:!appliance*]
2025-10-30 00:12:39.870167 | 
2025-10-30 00:12:39.870289 | TASK [include_role : start-zuul-console]
2025-10-30 00:12:39.923898 | controller | ok
2025-10-30 00:12:39.965926 | 
2025-10-30 00:12:39.966097 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-30 00:12:40.742088 | controller | ok
2025-10-30 00:12:40.767255 | 
2025-10-30 00:12:40.767381 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-30 00:12:42.658623 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-30 00:12:42.671289 | 
2025-10-30 00:12:42.671423 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-30 00:12:42.825616 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.839036 | 
2025-10-30 00:12:42.839219 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-30 00:12:42.856426 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.868460 | 
2025-10-30 00:12:42.868601 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-30 00:12:42.884080 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.894314 | 
2025-10-30 00:12:42.894471 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-30 00:12:42.912246 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.919453 | 
2025-10-30 00:12:42.919549 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-30 00:12:42.938067 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.948360 | 
2025-10-30 00:12:42.948492 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-30 00:12:42.963984 | controller | skipping: Conditional result was False
2025-10-30 00:12:42.979159 | 
2025-10-30 00:12:42.979261 | TASK [Disable Fedora Modular]
2025-10-30 00:12:43.585471 | controller | changed
2025-10-30 00:12:43.595012 | 
2025-10-30 00:12:43.595126 | TASK [Enable EPEL]
2025-10-30 00:12:43.619462 | controller | skipping: Conditional result was False
2025-10-30 00:12:43.632785 | 
2025-10-30 00:12:43.632884 | TASK [Register the RHEL node]
2025-10-30 00:12:43.777006 | 
2025-10-30 00:12:43.777159 | TASK [Show the subscription-manager status]
2025-10-30 00:12:43.992657 | controller | skipping: Conditional result was False
2025-10-30 00:12:43.998823 | 
2025-10-30 00:12:43.999029 | TASK [Enable EPEL on RHEL]
2025-10-30 00:12:44.141620 | controller | skipping: Conditional result was False
2025-10-30 00:12:44.157399 | 
2025-10-30 00:12:44.157556 | TASK [Install git and tox]
2025-10-30 00:14:15.808110 | controller | changed
2025-10-30 00:14:15.815355 | 
2025-10-30 00:14:15.815449 | TASK [include_role : prepare-workspace]
2025-10-30 00:14:15.835836 | controller | ok
2025-10-30 00:14:15.860114 | 
2025-10-30 00:14:15.860248 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-30 00:14:16.429614 | controller | ok
2025-10-30 00:14:16.444551 | 
2025-10-30 00:14:16.444844 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-30 00:14:32.034758 | controller | Output suppressed because no_log was given
2025-10-30 00:14:32.052724 | 
2025-10-30 00:14:32.052835 | TASK [include_role : prepare-workspace-openshift]
2025-10-30 00:14:32.079182 | controller | skipping: Conditional result was False
2025-10-30 00:14:32.104468 | 
2025-10-30 00:14:32.104544 | PLAY [all:!appliance]
2025-10-30 00:14:32.121057 | 
2025-10-30 00:14:32.121138 | TASK [Run add-build-sshkey role (RSA)]
2025-10-30 00:14:32.155727 | controller | ok
2025-10-30 00:14:32.200970 | 
2025-10-30 00:14:32.201103 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-30 00:14:32.430251 | controller -> localhost | ok
2025-10-30 00:14:32.436908 | 
2025-10-30 00:14:32.436988 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-30 00:14:32.483281 | controller | ok
2025-10-30 00:14:32.498107 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-30 00:14:32.505076 | 
2025-10-30 00:14:32.505152 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-30 00:14:33.079005 | controller -> localhost | Generating public/private rsa key pair.
2025-10-30 00:14:33.079220 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_rsa.
2025-10-30 00:14:33.079257 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_rsa.pub.
2025-10-30 00:14:33.079285 | controller -> localhost | The key fingerprint is:
2025-10-30 00:14:33.079310 | controller -> localhost | SHA256:hlkjAqWR1fZXRxnfXCW4t/gDeCVVlW1btdBMOd2vB9s zuul-build-sshkey
2025-10-30 00:14:33.079337 | controller -> localhost | The key's randomart image is:
2025-10-30 00:14:33.079362 | controller -> localhost | +---[RSA 2048]----+
2025-10-30 00:14:33.079387 | controller -> localhost | |  o+o.       +B=/|
2025-10-30 00:14:33.079412 | controller -> localhost | |  .+  o     o =XX|
2025-10-30 00:14:33.079436 | controller -> localhost | |  . ....o  . + oO|
2025-10-30 00:14:33.079460 | controller -> localhost | |     . =... o +..|
2025-10-30 00:14:33.079483 | controller -> localhost | |      o S. . = * |
2025-10-30 00:14:33.079540 | controller -> localhost | |       .  . + + E|
2025-10-30 00:14:33.079571 | controller -> localhost | |           . o . |
2025-10-30 00:14:33.079595 | controller -> localhost | |              o  |
2025-10-30 00:14:33.079620 | controller -> localhost | |               . |
2025-10-30 00:14:33.079647 | controller -> localhost | +----[SHA256]-----+
2025-10-30 00:14:33.079727 | controller -> localhost | ok: Runtime: 0:00:00.088163
2025-10-30 00:14:33.089382 | 
2025-10-30 00:14:33.089462 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-30 00:14:33.122919 | controller | ok
2025-10-30 00:14:33.137560 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-30 00:14:33.149654 | 
2025-10-30 00:14:33.149796 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-30 00:14:33.176065 | controller | skipping: Conditional result was False
2025-10-30 00:14:33.182759 | 
2025-10-30 00:14:33.182836 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-30 00:14:33.797733 | controller | changed
2025-10-30 00:14:33.804741 | 
2025-10-30 00:14:33.804838 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-30 00:14:34.144153 | controller | ok
2025-10-30 00:14:34.155356 | 
2025-10-30 00:14:34.155745 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-30 00:14:35.481050 | controller | changed
2025-10-30 00:14:35.487037 | 
2025-10-30 00:14:35.487111 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-30 00:14:36.789210 | controller | changed
2025-10-30 00:14:36.805545 | 
2025-10-30 00:14:36.805733 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-30 00:14:36.831809 | controller | skipping: Conditional result was False
2025-10-30 00:14:36.841933 | 
2025-10-30 00:14:36.842080 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-30 00:14:37.174179 | controller -> localhost | changed
2025-10-30 00:14:37.189377 | 
2025-10-30 00:14:37.189509 | TASK [add-build-sshkey : Add back temp key]
2025-10-30 00:14:37.449029 | controller -> localhost | Identity added: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_rsa (zuul-build-sshkey)
2025-10-30 00:14:37.449367 | controller -> localhost | ok: Runtime: 0:00:00.014833
2025-10-30 00:14:37.465010 | 
2025-10-30 00:14:37.465170 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-30 00:14:37.976434 | controller | ok
2025-10-30 00:14:37.981647 | 
2025-10-30 00:14:37.981744 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-30 00:14:38.016554 | controller | skipping: Conditional result was False
2025-10-30 00:14:38.027355 | 
2025-10-30 00:14:38.027460 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-30 00:14:38.058021 | controller | ok
2025-10-30 00:14:38.074059 | 
2025-10-30 00:14:38.074171 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-30 00:14:38.325327 | controller -> localhost | ok
2025-10-30 00:14:38.336659 | 
2025-10-30 00:14:38.336826 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-30 00:14:38.369972 | controller | ok
2025-10-30 00:14:38.384833 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-30 00:14:38.393289 | 
2025-10-30 00:14:38.393404 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-30 00:14:38.694330 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-30 00:14:38.694536 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_ecdsa.
2025-10-30 00:14:38.694564 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_ecdsa.pub.
2025-10-30 00:14:38.694594 | controller -> localhost | The key fingerprint is:
2025-10-30 00:14:38.694614 | controller -> localhost | SHA256:adgazZRkrvuK/980LInhXUzQPCkqmjxEZ35B2O5e1Ok zuul-build-sshkey
2025-10-30 00:14:38.694633 | controller -> localhost | The key's randomart image is:
2025-10-30 00:14:38.694651 | controller -> localhost | +---[ECDSA 521]---+
2025-10-30 00:14:38.694691 | controller -> localhost | |       ++ .o .   |
2025-10-30 00:14:38.694711 | controller -> localhost | |    . ++o...=    |
2025-10-30 00:14:38.694729 | controller -> localhost | |   . + .+o o.o   |
2025-10-30 00:14:38.694746 | controller -> localhost | |    . oB+..oo    |
2025-10-30 00:14:38.694763 | controller -> localhost | |   o o++S. .o    |
2025-10-30 00:14:38.694780 | controller -> localhost | |    =  *.+.+E    |
2025-10-30 00:14:38.694796 | controller -> localhost | |     .o.o.+ +    |
2025-10-30 00:14:38.694813 | controller -> localhost | |     . ..  + .   |
2025-10-30 00:14:38.694829 | controller -> localhost | |    ..ooo.. .    |
2025-10-30 00:14:38.694846 | controller -> localhost | +----[SHA256]-----+
2025-10-30 00:14:38.694895 | controller -> localhost | ok: Runtime: 0:00:00.011874
2025-10-30 00:14:38.701492 | 
2025-10-30 00:14:38.701728 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-30 00:14:38.721116 | controller | ok
2025-10-30 00:14:38.733016 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-30 00:14:38.742719 | 
2025-10-30 00:14:38.742806 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-30 00:14:38.766340 | controller | skipping: Conditional result was False
2025-10-30 00:14:38.772531 | 
2025-10-30 00:14:38.772697 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-30 00:14:39.244913 | controller | changed
2025-10-30 00:14:39.258005 | 
2025-10-30 00:14:39.258189 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-30 00:14:39.617136 | controller | ok
2025-10-30 00:14:39.630775 | 
2025-10-30 00:14:39.630953 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-30 00:14:41.139931 | controller | changed
2025-10-30 00:14:41.152628 | 
2025-10-30 00:14:41.152806 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-30 00:14:42.594073 | controller | changed
2025-10-30 00:14:42.601890 | 
2025-10-30 00:14:42.601970 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-30 00:14:42.627169 | controller | skipping: Conditional result was False
2025-10-30 00:14:42.635737 | 
2025-10-30 00:14:42.635826 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-30 00:14:42.946557 | controller -> localhost | changed
2025-10-30 00:14:42.959606 | 
2025-10-30 00:14:42.959714 | TASK [add-build-sshkey : Add back temp key]
2025-10-30 00:14:43.239850 | controller -> localhost | Identity added: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/c0c6f1a3cb6b44ddb8a385b503872c7f_id_ecdsa (zuul-build-sshkey)
2025-10-30 00:14:43.240198 | controller -> localhost | ok: Runtime: 0:00:00.006925
2025-10-30 00:14:43.256470 | 
2025-10-30 00:14:43.256619 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-30 00:14:43.615560 | controller | ok
2025-10-30 00:14:43.623064 | 
2025-10-30 00:14:43.623144 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-30 00:14:43.658435 | controller | skipping: Conditional result was False
2025-10-30 00:14:43.672018 | 
2025-10-30 00:14:43.672110 | TASK [include_role : remove-zuul-sshkey]
2025-10-30 00:14:43.696656 | controller | skipping: Conditional result was False
2025-10-30 00:14:43.708993 | 
2025-10-30 00:14:43.709121 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-30 00:14:44.084035 | controller | ok: "logs"
2025-10-30 00:14:44.084431 | controller | ok: All items complete
2025-10-30 00:14:44.084511 | 
2025-10-30 00:14:44.375659 | controller | ok: "artifacts"
2025-10-30 00:14:44.664859 | controller | ok: "docs"
2025-10-30 00:14:44.690423 | 
2025-10-30 00:14:44.690617 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-30 00:14:45.051751 | controller | changed: "logs"
2025-10-30 00:14:45.417950 | controller | changed: "artifacts"
2025-10-30 00:14:45.722200 | controller | changed: "docs"
2025-10-30 00:14:45.762221 | 
2025-10-30 00:14:45.762332 | PLAY RECAP
2025-10-30 00:14:45.762411 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-30 00:14:45.762440 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-30 00:14:45.762458 | 
2025-10-30 00:14:45.907621 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-30 00:14:45.910044 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-30 00:14:46.549484 | 
2025-10-30 00:14:46.549689 | PLAY [all]
2025-10-30 00:14:46.575088 | 
2025-10-30 00:14:46.575245 | TASK [Install binary dependencies]
2025-10-30 00:14:46.625210 | controller | ok
2025-10-30 00:14:46.650010 | 
2025-10-30 00:14:46.650151 | TASK [bindep : Include find tasks]
2025-10-30 00:14:46.692012 | controller | ok
2025-10-30 00:14:46.702768 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-30 00:14:46.711503 | 
2025-10-30 00:14:46.711631 | TASK [bindep : Look for bindep.txt]
2025-10-30 00:14:47.347388 | controller | ok
2025-10-30 00:14:47.356342 | 
2025-10-30 00:14:47.357309 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:14:47.385344 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.395453 | 
2025-10-30 00:14:47.395564 | TASK [bindep : Look for other-requirements.txt]
2025-10-30 00:14:47.702676 | controller | ok
2025-10-30 00:14:47.708611 | 
2025-10-30 00:14:47.708702 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:14:47.742388 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.749445 | 
2025-10-30 00:14:47.749550 | TASK [bindep : Look for bindep fallback file]
2025-10-30 00:14:47.773400 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.780308 | 
2025-10-30 00:14:47.780413 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:14:47.814491 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.825288 | 
2025-10-30 00:14:47.825398 | TASK [bindep : Include bindep tasks]
2025-10-30 00:14:47.849800 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.856521 | 
2025-10-30 00:14:47.856595 | TASK [bindep : Include install tasks]
2025-10-30 00:14:47.882311 | controller | skipping: Conditional result was False
2025-10-30 00:14:47.888910 | 
2025-10-30 00:14:47.888983 | LOOP [bindep : Include package tasks]
2025-10-30 00:14:47.944054 | 
2025-10-30 00:14:47.944631 | TASK [Run test-setup role]
2025-10-30 00:14:47.967374 | controller | ok
2025-10-30 00:14:47.991719 | 
2025-10-30 00:14:47.991838 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-30 00:14:48.334401 | controller | ok
2025-10-30 00:14:48.347341 | 
2025-10-30 00:14:48.347504 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-30 00:14:48.491312 | controller | skipping: Conditional result was False
2025-10-30 00:14:48.518968 | 
2025-10-30 00:14:48.519080 | PLAY RECAP
2025-10-30 00:14:48.519131 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-30 00:14:48.519156 | 
2025-10-30 00:14:48.624324 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-30 00:14:48.625205 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-30 00:14:49.222614 | 
2025-10-30 00:14:49.222784 | PLAY [controller]
2025-10-30 00:14:49.243633 | 
2025-10-30 00:14:49.243770 | TASK [Create the /root directory]
2025-10-30 00:14:50.010983 | controller | ok
2025-10-30 00:14:50.017260 | 
2025-10-30 00:14:50.017339 | TASK [Install glibc-langpack-en]
2025-10-30 00:14:58.220277 | controller | ok: Nothing to do
2025-10-30 00:14:58.231624 | 
2025-10-30 00:14:58.231723 | TASK [Ensure controller directory exists]
2025-10-30 00:14:58.675983 | controller | changed
2025-10-30 00:14:58.689962 | 
2025-10-30 00:14:58.690119 | TASK [Install container runtime]
2025-10-30 00:14:58.767371 | controller | ok
2025-10-30 00:14:58.821775 | 
2025-10-30 00:14:58.821929 | LOOP [ensure-podman : Find distribution installation]
2025-10-30 00:14:58.871801 | controller | ok: "/var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-30 00:14:58.889400 | controller | included: /var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-30 00:14:58.900112 | 
2025-10-30 00:14:58.900274 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-30 00:16:20.359815 | controller | changed
2025-10-30 00:16:20.375213 | 
2025-10-30 00:16:20.375534 | TASK [ensure-podman : Fetch podman version]
2025-10-30 00:16:21.159984 | controller | Client:       Podman Engine
2025-10-30 00:16:21.186517 | controller | Version:      4.6.2
2025-10-30 00:16:21.186561 | controller | API Version:  4.6.2
2025-10-30 00:16:21.186569 | controller | Go Version:   go1.19.12
2025-10-30 00:16:21.186587 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-30 00:16:21.186594 | controller | OS/Arch:      linux/amd64
2025-10-30 00:16:21.540574 | controller | ok: Runtime: 0:00:00.223332
2025-10-30 00:16:21.556203 | 
2025-10-30 00:16:21.556396 | TASK [ensure-podman : Print podman version installed]
2025-10-30 00:16:21.596798 | Podman version: Client:       Podman Engine
2025-10-30 00:16:21.597072 | Version:      4.6.2
2025-10-30 00:16:21.597138 | API Version:  4.6.2
2025-10-30 00:16:21.597186 | Go Version:   go1.19.12
2025-10-30 00:16:21.597226 | Built:        Mon Aug 28 19:38:31 2023
2025-10-30 00:16:21.597274 | OS/Arch:      linux/amd64
2025-10-30 00:16:21.611261 | 
2025-10-30 00:16:21.611441 | TASK [ensure-podman : Validate podman engine]
2025-10-30 00:16:21.779816 | controller | skipping: Conditional result was False
2025-10-30 00:16:21.788592 | 
2025-10-30 00:16:21.788784 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-30 00:16:21.814169 | controller | skipping: Conditional result was False
2025-10-30 00:16:21.833975 | 
2025-10-30 00:16:21.834120 | TASK [Ensure python3.8 is present]
2025-10-30 00:16:21.860909 | controller | skipping: Conditional result was False
2025-10-30 00:16:21.869071 | 
2025-10-30 00:16:21.869165 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-30 00:16:21.891639 | controller | ok
2025-10-30 00:16:21.919786 | 
2025-10-30 00:16:21.919892 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-30 00:16:25.601796 | controller | ok: Nothing to do
2025-10-30 00:16:25.616892 | 
2025-10-30 00:16:25.617081 | TASK [our-ensure-python : Also install python3-devel]
2025-10-30 00:16:38.914743 | controller | changed
2025-10-30 00:16:38.928187 | 
2025-10-30 00:16:38.928312 | TASK [Run ensure-virtualenv role]
2025-10-30 00:16:38.948587 | controller | ok
2025-10-30 00:16:38.973046 | 
2025-10-30 00:16:38.973189 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-30 00:16:39.370287 | controller | /usr/bin/virtualenv
2025-10-30 00:16:39.611110 | controller | ok: Runtime: 0:00:00.004457
2025-10-30 00:16:39.620623 | 
2025-10-30 00:16:39.621046 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-30 00:16:39.641649 | controller | skipping: Conditional result was False
2025-10-30 00:16:39.642029 | controller | ok: All items complete
2025-10-30 00:16:39.642073 | 
2025-10-30 00:16:39.704626 | 
2025-10-30 00:16:39.704776 | TASK [Find the full path of the Python interpreter]
2025-10-30 00:16:40.128413 | controller | /usr/bin/python3
2025-10-30 00:16:40.333711 | controller | ok
2025-10-30 00:16:40.339927 | 
2025-10-30 00:16:40.340014 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-30 00:16:41.675188 | controller | created virtual environment CPython3.11.0.final.0-64 in 722ms
2025-10-30 00:16:41.724492 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-30 00:16:41.724549 | 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-30 00:16:41.724567 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-30 00:16:41.724589 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-30 00:16:41.969278 | controller | changed
2025-10-30 00:16:41.976508 | 
2025-10-30 00:16:41.976603 | TASK [Set selinux package]
2025-10-30 00:16:42.000288 | controller | ok
2025-10-30 00:16:42.006379 | 
2025-10-30 00:16:42.006456 | TASK [Set selinux package (Fedora)]
2025-10-30 00:16:42.048319 | controller | ok
2025-10-30 00:16:42.053996 | 
2025-10-30 00:16:42.054081 | TASK [Install selinux into virtualenv]
2025-10-30 00:16:44.665096 | controller | Collecting selinux-please-lie-to-me
2025-10-30 00:16:44.806253 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-30 00:16:45.341171 | controller | Collecting setuptools<50.0.0
2025-10-30 00:16:45.356234 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-30 00:16:45.472877 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.2 MB/s eta 0:00:00
2025-10-30 00:16:45.628909 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-30 00:16:45.629218 | controller |   Attempting uninstall: setuptools
2025-10-30 00:16:45.634179 | controller |     Found existing installation: setuptools 62.6.0
2025-10-30 00:16:45.746247 | controller |     Uninstalling setuptools-62.6.0:
2025-10-30 00:16:45.761462 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-30 00:16:46.525663 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-30 00:16:46.738653 | controller |
2025-10-30 00:16:46.951131 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-30 00:16:46.951183 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-30 00:16:47.230594 | controller | ok: Runtime: 0:00:04.417903
2025-10-30 00:16:47.239612 | 
2025-10-30 00:16:47.239761 | TASK [Install pytest-forked into virtualenv]
2025-10-30 00:16:48.464932 | controller | Collecting pytest-forked
2025-10-30 00:16:48.552988 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-30 00:16:48.612637 | controller | Collecting py
2025-10-30 00:16:48.626000 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-30 00:16:48.661843 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-10-30 00:16:48.832044 | controller | Collecting pytest>=3.10
2025-10-30 00:16:48.845036 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-30 00:16:48.903347 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.6 MB/s eta 0:00:00
2025-10-30 00:16:48.959789 | controller | Collecting iniconfig>=1
2025-10-30 00:16:48.971857 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-30 00:16:49.038701 | controller | Collecting packaging>=20
2025-10-30 00:16:49.051087 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-30 00:16:49.062368 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.4 MB/s eta 0:00:00
2025-10-30 00:16:49.109312 | controller | Collecting pluggy<2,>=1.5
2025-10-30 00:16:49.121066 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-30 00:16:49.195436 | controller | Collecting pygments>=2.7.2
2025-10-30 00:16:49.207270 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-30 00:16:49.324586 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-10-30 00:16:49.456244 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-30 00:16:51.678986 | 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-30 00:16:51.695525 | controller |
2025-10-30 00:16:51.887276 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-30 00:16:51.887327 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-30 00:16:52.395319 | controller | ok: Runtime: 0:00:04.170234
2025-10-30 00:16:52.410380 | 
2025-10-30 00:16:52.410510 | TASK [Update pip]
2025-10-30 00:16:53.520746 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-30 00:16:53.808919 | controller | Collecting pip
2025-10-30 00:16:53.993654 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-30 00:16:54.293673 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 6.0 MB/s eta 0:00:00
2025-10-30 00:16:54.416947 | controller | Installing collected packages: pip
2025-10-30 00:16:54.417252 | controller |   Attempting uninstall: pip
2025-10-30 00:16:54.421732 | controller |     Found existing installation: pip 22.2.2
2025-10-30 00:16:54.714178 | controller |     Uninstalling pip-22.2.2:
2025-10-30 00:16:54.743997 | controller |       Successfully uninstalled pip-22.2.2
2025-10-30 00:16:56.493515 | controller | Successfully installed pip-25.3
2025-10-30 00:16:57.063608 | controller | ok: Runtime: 0:00:03.803054
2025-10-30 00:16:57.079097 | 
2025-10-30 00:16:57.080000 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-30 00:16:57.659601 | controller | changed
2025-10-30 00:16:57.673280 | 
2025-10-30 00:16:57.673465 | TASK [Install ansible into virtualenv]
2025-10-30 00:16:58.733079 | controller | Processing ./src/github.com/ansible/ansible
2025-10-30 00:16:58.739444 | controller |   Installing build dependencies: started
2025-10-30 00:17:00.745651 | controller |   Installing build dependencies: finished with status 'done'
2025-10-30 00:17:02.359320 | controller |   Getting requirements to build wheel: started
2025-10-30 00:17:02.359389 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-30 00:17:02.360933 | controller |   Preparing metadata (pyproject.toml): started
2025-10-30 00:17:03.321345 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-30 00:17:03.323450 | 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-30 00:17:03.328438 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-30 00:17:03.825004 | controller | ERROR
2025-10-30 00:17:03.825317 | controller | {
2025-10-30 00:17:03.825381 | controller |   "delta": "0:00:05.375220",
2025-10-30 00:17:03.825424 | controller |   "end": "2025-10-30 00:17:03.481465",
2025-10-30 00:17:03.825463 | controller |   "msg": "non-zero return code",
2025-10-30 00:17:03.825519 | controller |   "rc": 1,
2025-10-30 00:17:03.825556 | controller |   "start": "2025-10-30 00:16:58.106245"
2025-10-30 00:17:03.825594 | controller | }
failure
2025-10-30 00:17:03.828899 | 
2025-10-30 00:17:03.828959 | PLAY RECAP
2025-10-30 00:17:03.829017 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-30 00:17:03.829047 | 
2025-10-30 00:17:03.956504 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-30 00:17:03.958069 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-30 00:17:04.575621 | 
2025-10-30 00:17:04.575762 | PLAY [all]
2025-10-30 00:17:04.598008 | 
2025-10-30 00:17:04.598131 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-30 00:17:05.451104 | controller | changed: non-zero return code
2025-10-30 00:17:05.464239 | 
2025-10-30 00:17:05.464409 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-30 00:17:05.492110 | controller | skipping: Conditional result was False
2025-10-30 00:17:05.499170 | 
2025-10-30 00:17:05.499283 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-30 00:17:05.522797 | 
2025-10-30 00:17:05.523032 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-30 00:17:05.543551 | 
2025-10-30 00:17:05.543793 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-30 00:17:05.557963 | controller | skipping: Conditional result was False
2025-10-30 00:17:05.564898 | 
2025-10-30 00:17:05.564975 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-30 00:17:05.597386 | 
2025-10-30 00:17:05.597699 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-30 00:17:05.622076 | controller | skipping: Conditional result was False
2025-10-30 00:17:05.629727 | 
2025-10-30 00:17:05.629860 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-30 00:17:05.654159 | controller | skipping: Conditional result was False
2025-10-30 00:17:05.661070 | 
2025-10-30 00:17:05.661179 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-30 00:17:05.685469 | controller | skipping: Conditional result was False
2025-10-30 00:17:05.712551 | 
2025-10-30 00:17:05.712648 | PLAY RECAP
2025-10-30 00:17:05.712739 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-30 00:17:05.712762 | 
2025-10-30 00:17:05.834201 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-30 00:17:05.835847 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-30 00:17:06.450755 | 
2025-10-30 00:17:06.450875 | PLAY [all:!appliance*]
2025-10-30 00:17:06.471865 | 
2025-10-30 00:17:06.471967 | TASK [unregister the node]
2025-10-30 00:17:06.615137 | controller | skipping: Conditional result was False
2025-10-30 00:17:06.623906 | 
2025-10-30 00:17:06.624036 | TASK [include_role : fetch-output]
2025-10-30 00:17:06.676957 | controller | ok
2025-10-30 00:17:06.707538 | 
2025-10-30 00:17:06.707715 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-30 00:17:06.794617 | controller | skipping: Conditional result was False
2025-10-30 00:17:06.807783 | 
2025-10-30 00:17:06.807932 | TASK [fetch-output : Set log path for single node]
2025-10-30 00:17:06.861933 | controller | ok
2025-10-30 00:17:06.867755 | 
2025-10-30 00:17:06.867852 | LOOP [fetch-output : Ensure local output dirs]
2025-10-30 00:17:07.350031 | controller -> localhost | ok: "/var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/logs"
2025-10-30 00:17:07.572789 | controller -> localhost | changed: "/var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/artifacts"
2025-10-30 00:17:07.778890 | controller -> localhost | changed: "/var/lib/zuul/builds/c0c6f1a3cb6b44ddb8a385b503872c7f/work/docs"
2025-10-30 00:17:07.793600 | 
2025-10-30 00:17:07.794409 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-30 00:17:09.345008 | controller | changed:
2025-10-30 00:17:09.345192 | controller | .d..t...... ./
2025-10-30 00:17:09.345220 | controller | cd+++++++++ controller/
2025-10-30 00:17:09.345252 | controller | changed: All items complete
2025-10-30 00:17:09.345273 | 
2025-10-30 00:17:10.396358 | controller | changed: .d..t...... ./
2025-10-30 00:17:11.483193 | controller | changed: .d..t...... ./
2025-10-30 00:17:11.502078 | 
2025-10-30 00:17:11.502212 | TASK [include_role : fetch-output-openshift]
2025-10-30 00:17:11.528252 | controller | skipping: Conditional result was False
2025-10-30 00:17:11.535753 | 
2025-10-30 00:17:11.535852 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-30 00:17:11.581038 | controller | skipping: Conditional result was False
2025-10-30 00:17:11.594238 | controller | skipping: Conditional result was False
2025-10-30 00:17:11.635361 | 
2025-10-30 00:17:11.635488 | PLAY [localhost]
2025-10-30 00:17:11.652935 | 
2025-10-30 00:17:11.653129 | TASK [Run Zuul manifest role]
2025-10-30 00:17:11.674284 | localhost | ok
2025-10-30 00:17:11.693252 | 
2025-10-30 00:17:11.693477 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-30 00:17:12.059894 | localhost | changed
2025-10-30 00:17:12.064827 | 
2025-10-30 00:17:12.064896 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-30 00:17:12.094322 | localhost | ok
2025-10-30 00:17:12.103495 | 
2025-10-30 00:17:12.103592 | TASK [Set zuul-log-path fact]
2025-10-30 00:17:12.128456 | localhost | ok
2025-10-30 00:17:12.177219 | 
2025-10-30 00:17:12.177339 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-30 00:17:12.217093 | localhost | ok
2025-10-30 00:17:12.230713 | 
2025-10-30 00:17:12.230835 | LOOP [Run upload-logs-swift role]
2025-10-30 00:17:12.286855 | localhost | Output suppressed because no_log was given
2025-10-30 00:17:12.336145 | 
2025-10-30 00:17:12.336311 | TASK [Set zuul-log-path fact]
2025-10-30 00:17:12.372068 | localhost | skipping: Conditional result was False
2025-10-30 00:17:12.380445 | 
2025-10-30 00:17:12.380613 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-30 00:17:12.854451 | localhost -> localhost | ok: Runtime: 0:00:00.010095
2025-10-30 00:17:12.860728 | 
2025-10-30 00:17:12.860815 | TASK [upload-logs-swift : Upload logs to swift]