2025-10-04 00:13:11.448990 | Job console starting...
2025-10-04 00:13:11.459985 | Updating repositories
2025-10-04 00:13:11.609589 | Preparing job workspace
2025-10-04 00:13:15.605523 | Running Ansible setup...
2025-10-04 00:13:22.036995 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-04 00:13:22.698841 | 
2025-10-04 00:13:22.698973 | PLAY [localhost]
2025-10-04 00:13:22.707863 | 
2025-10-04 00:13:22.707976 | TASK [Gathering Facts]
2025-10-04 00:13:23.710869 | localhost | ok
2025-10-04 00:13:23.747739 | 
2025-10-04 00:13:23.747952 | TASK [Setup log path fact]
2025-10-04 00:13:23.776465 | localhost | ok
2025-10-04 00:13:23.796473 | 
2025-10-04 00:13:23.796612 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-04 00:13:23.826465 | localhost | ok
2025-10-04 00:13:23.836123 | 
2025-10-04 00:13:23.836266 | TASK [emit-job-header : Print job information]
2025-10-04 00:13:23.885611 | # Job Information
2025-10-04 00:13:23.885811 | Ansible Version: 2.15.12
2025-10-04 00:13:23.885847 | Job: ansible-test-sanity-docker-milestone
2025-10-04 00:13:23.886143 | Pipeline: periodic
2025-10-04 00:13:23.886180 | Executor: ze04.softwarefactory-project.io
2025-10-04 00:13:23.886202 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-04 00:13:23.886225 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/248/ansible/2482680b41084a73b6ccfca84548e7eb/
2025-10-04 00:13:23.886245 | Event ID: 94a13ac06c46427a92df5bbab63fdd0f
2025-10-04 00:13:23.891821 | 
2025-10-04 00:13:23.891901 | LOOP [emit-job-header : Print node information]
2025-10-04 00:13:24.053798 | localhost | ok:
2025-10-04 00:13:24.054006 | localhost | # Node Information
2025-10-04 00:13:24.054034 | localhost | Inventory Hostname: controller
2025-10-04 00:13:24.054055 | localhost | Hostname: ip-172-16-33-13
2025-10-04 00:13:24.054073 | localhost | Username: zuul-worker
2025-10-04 00:13:24.054094 | localhost | Distro: Fedora 37
2025-10-04 00:13:24.054112 | localhost | Provider: ansible-us-east-2
2025-10-04 00:13:24.054130 | localhost | Region: us-east-2
2025-10-04 00:13:24.054147 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-04 00:13:24.054163 | localhost | Product Name: t3.small
2025-10-04 00:13:24.054180 | localhost | Interface IP: 3.134.244.104
2025-10-04 00:13:24.074562 | 
2025-10-04 00:13:24.074771 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-04 00:13:24.539398 | localhost -> localhost | changed
2025-10-04 00:13:24.546451 | 
2025-10-04 00:13:24.546559 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-04 00:13:25.516093 | localhost -> localhost | changed
2025-10-04 00:13:25.556469 | 
2025-10-04 00:13:25.556724 | PLAY [all:!appliance*]
2025-10-04 00:13:25.587712 | 
2025-10-04 00:13:25.587850 | TASK [include_role : start-zuul-console]
2025-10-04 00:13:25.608533 | controller | ok
2025-10-04 00:13:25.625170 | 
2025-10-04 00:13:25.625319 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-04 00:13:26.280046 | controller | ok
2025-10-04 00:13:26.314406 | 
2025-10-04 00:13:26.314585 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-04 00:13:28.057495 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-04 00:13:28.067023 | 
2025-10-04 00:13:28.067091 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-04 00:13:28.203938 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.210611 | 
2025-10-04 00:13:28.210697 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-04 00:13:28.234936 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.245261 | 
2025-10-04 00:13:28.245395 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-04 00:13:28.271411 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.281176 | 
2025-10-04 00:13:28.281301 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-04 00:13:28.307600 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.317810 | 
2025-10-04 00:13:28.317934 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-04 00:13:28.344292 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.351283 | 
2025-10-04 00:13:28.351369 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-04 00:13:28.376766 | controller | skipping: Conditional result was False
2025-10-04 00:13:28.392580 | 
2025-10-04 00:13:28.392790 | TASK [Disable Fedora Modular]
2025-10-04 00:13:29.172023 | controller | changed
2025-10-04 00:13:29.189330 | 
2025-10-04 00:13:29.189476 | TASK [Enable EPEL]
2025-10-04 00:13:29.227094 | controller | skipping: Conditional result was False
2025-10-04 00:13:29.237066 | 
2025-10-04 00:13:29.238442 | TASK [Register the RHEL node]
2025-10-04 00:13:29.432207 | 
2025-10-04 00:13:29.432445 | TASK [Show the subscription-manager status]
2025-10-04 00:13:29.648800 | controller | skipping: Conditional result was False
2025-10-04 00:13:29.656492 | 
2025-10-04 00:13:29.656574 | TASK [Enable EPEL on RHEL]
2025-10-04 00:13:29.802345 | controller | skipping: Conditional result was False
2025-10-04 00:13:29.810239 | 
2025-10-04 00:13:29.810321 | TASK [Install git and tox]
2025-10-04 00:14:56.707941 | controller | changed
2025-10-04 00:14:56.715101 | 
2025-10-04 00:14:56.715179 | TASK [include_role : prepare-workspace]
2025-10-04 00:14:56.736214 | controller | ok
2025-10-04 00:14:56.764454 | 
2025-10-04 00:14:56.764586 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-04 00:14:57.260368 | controller | ok
2025-10-04 00:14:57.274029 | 
2025-10-04 00:14:57.274191 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-04 00:15:13.355558 | controller | Output suppressed because no_log was given
2025-10-04 00:15:13.384036 | 
2025-10-04 00:15:13.384248 | TASK [include_role : prepare-workspace-openshift]
2025-10-04 00:15:13.412414 | controller | skipping: Conditional result was False
2025-10-04 00:15:13.447227 | 
2025-10-04 00:15:13.447362 | PLAY [all:!appliance]
2025-10-04 00:15:13.468897 | 
2025-10-04 00:15:13.469003 | TASK [Run add-build-sshkey role (RSA)]
2025-10-04 00:15:13.499237 | controller | ok
2025-10-04 00:15:13.515882 | 
2025-10-04 00:15:13.515983 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-04 00:15:13.776632 | controller -> localhost | ok
2025-10-04 00:15:13.783064 | 
2025-10-04 00:15:13.783128 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-04 00:15:13.823440 | controller | ok
2025-10-04 00:15:13.842236 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-04 00:15:13.848175 | 
2025-10-04 00:15:13.848233 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-04 00:15:14.382407 | controller -> localhost | Generating public/private rsa key pair.
2025-10-04 00:15:14.382670 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_rsa.
2025-10-04 00:15:14.382749 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_rsa.pub.
2025-10-04 00:15:14.382781 | controller -> localhost | The key fingerprint is:
2025-10-04 00:15:14.382810 | controller -> localhost | SHA256:FBS01++urydrOf0JLpAMXMK4P2aqNLH844p9d8hDgLg zuul-build-sshkey
2025-10-04 00:15:14.382838 | controller -> localhost | The key's randomart image is:
2025-10-04 00:15:14.382866 | controller -> localhost | +---[RSA 2048]----+
2025-10-04 00:15:14.382905 | controller -> localhost | |      oo=.       |
2025-10-04 00:15:14.382943 | controller -> localhost | |     . o + .     |
2025-10-04 00:15:14.382977 | controller -> localhost | |  . . o = . .    |
2025-10-04 00:15:14.383006 | controller -> localhost | | . . o + .   .   |
2025-10-04 00:15:14.383032 | controller -> localhost | |  ..  o S .   .  |
2025-10-04 00:15:14.383070 | controller -> localhost | | E. o  * +   .   |
2025-10-04 00:15:14.383106 | controller -> localhost | |   =  * o .  +.  |
2025-10-04 00:15:14.383137 | controller -> localhost | |  + o+ = . .*.+ .|
2025-10-04 00:15:14.383165 | controller -> localhost | | . +=oo o  .=Xoo.|
2025-10-04 00:15:14.383196 | controller -> localhost | +----[SHA256]-----+
2025-10-04 00:15:14.383261 | controller -> localhost | ok: Runtime: 0:00:00.121728
2025-10-04 00:15:14.396739 | 
2025-10-04 00:15:14.396838 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-04 00:15:14.461502 | controller | ok
2025-10-04 00:15:14.473708 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-04 00:15:14.487204 | 
2025-10-04 00:15:14.487403 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-04 00:15:14.512813 | controller | skipping: Conditional result was False
2025-10-04 00:15:14.519962 | 
2025-10-04 00:15:14.520032 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-04 00:15:15.155863 | controller | changed
2025-10-04 00:15:15.173041 | 
2025-10-04 00:15:15.173250 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-04 00:15:15.552426 | controller | ok
2025-10-04 00:15:15.569107 | 
2025-10-04 00:15:15.569280 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-04 00:15:16.883121 | controller | changed
2025-10-04 00:15:16.889053 | 
2025-10-04 00:15:16.889115 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-04 00:15:18.203321 | controller | changed
2025-10-04 00:15:18.220141 | 
2025-10-04 00:15:18.220516 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-04 00:15:18.249248 | controller | skipping: Conditional result was False
2025-10-04 00:15:18.259411 | 
2025-10-04 00:15:18.259526 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-04 00:15:18.705320 | controller -> localhost | changed
2025-10-04 00:15:18.739151 | 
2025-10-04 00:15:18.739379 | TASK [add-build-sshkey : Add back temp key]
2025-10-04 00:15:19.037823 | controller -> localhost | Identity added: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_rsa (zuul-build-sshkey)
2025-10-04 00:15:19.038139 | controller -> localhost | ok: Runtime: 0:00:00.008616
2025-10-04 00:15:19.048717 | 
2025-10-04 00:15:19.048835 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-04 00:15:19.513602 | controller | ok
2025-10-04 00:15:19.522420 | 
2025-10-04 00:15:19.522544 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-04 00:15:19.569170 | controller | skipping: Conditional result was False
2025-10-04 00:15:19.589177 | 
2025-10-04 00:15:19.589313 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-04 00:15:19.625251 | controller | ok
2025-10-04 00:15:19.651800 | 
2025-10-04 00:15:19.651938 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-04 00:15:19.911972 | controller -> localhost | ok
2025-10-04 00:15:19.925563 | 
2025-10-04 00:15:19.925691 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-04 00:15:19.968501 | controller | ok
2025-10-04 00:15:19.983924 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-04 00:15:19.992006 | 
2025-10-04 00:15:19.992087 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-04 00:15:20.302915 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-04 00:15:20.303130 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_ecdsa.
2025-10-04 00:15:20.303170 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_ecdsa.pub.
2025-10-04 00:15:20.303210 | controller -> localhost | The key fingerprint is:
2025-10-04 00:15:20.303239 | controller -> localhost | SHA256:IDIAxgi2oGk1oMIO9Z9lN+ueBoutT0UnYB0za5f/KAA zuul-build-sshkey
2025-10-04 00:15:20.303268 | controller -> localhost | The key's randomart image is:
2025-10-04 00:15:20.303294 | controller -> localhost | +---[ECDSA 521]---+
2025-10-04 00:15:20.303320 | controller -> localhost | |X+oo    o.+.     |
2025-10-04 00:15:20.303344 | controller -> localhost | |O=o..  . ..+ .   |
2025-10-04 00:15:20.303368 | controller -> localhost | |*+o o . E B +    |
2025-10-04 00:15:20.303393 | controller -> localhost | |=  o o = = * .   |
2025-10-04 00:15:20.303418 | controller -> localhost | | .    o S +   .  |
2025-10-04 00:15:20.303443 | controller -> localhost | |        .o .   o |
2025-10-04 00:15:20.303469 | controller -> localhost | |       o.o. . . .|
2025-10-04 00:15:20.303495 | controller -> localhost | |      ..o... .   |
2025-10-04 00:15:20.303519 | controller -> localhost | |      .o..o      |
2025-10-04 00:15:20.303544 | controller -> localhost | +----[SHA256]-----+
2025-10-04 00:15:20.303601 | controller -> localhost | ok: Runtime: 0:00:00.008831
2025-10-04 00:15:20.313590 | 
2025-10-04 00:15:20.313743 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-04 00:15:20.346042 | controller | ok
2025-10-04 00:15:20.354651 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-04 00:15:20.366124 | 
2025-10-04 00:15:20.366253 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-04 00:15:20.391156 | controller | skipping: Conditional result was False
2025-10-04 00:15:20.400864 | 
2025-10-04 00:15:20.400994 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-04 00:15:20.846194 | controller | changed
2025-10-04 00:15:20.856587 | 
2025-10-04 00:15:20.856747 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-04 00:15:21.223387 | controller | ok
2025-10-04 00:15:21.237023 | 
2025-10-04 00:15:21.237145 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-04 00:15:22.539704 | controller | changed
2025-10-04 00:15:22.545935 | 
2025-10-04 00:15:22.546003 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-04 00:15:23.799475 | controller | changed
2025-10-04 00:15:23.805503 | 
2025-10-04 00:15:23.805571 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-04 00:15:23.837653 | controller | skipping: Conditional result was False
2025-10-04 00:15:23.849937 | 
2025-10-04 00:15:23.850057 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-04 00:15:24.152773 | controller -> localhost | changed
2025-10-04 00:15:24.170081 | 
2025-10-04 00:15:24.170204 | TASK [add-build-sshkey : Add back temp key]
2025-10-04 00:15:24.480258 | controller -> localhost | Identity added: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/2482680b41084a73b6ccfca84548e7eb_id_ecdsa (zuul-build-sshkey)
2025-10-04 00:15:24.480549 | controller -> localhost | ok: Runtime: 0:00:00.007833
2025-10-04 00:15:24.488405 | 
2025-10-04 00:15:24.488574 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-04 00:15:24.839391 | controller | ok
2025-10-04 00:15:24.849968 | 
2025-10-04 00:15:24.850103 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-04 00:15:24.875565 | controller | skipping: Conditional result was False
2025-10-04 00:15:24.892402 | 
2025-10-04 00:15:24.892529 | TASK [include_role : remove-zuul-sshkey]
2025-10-04 00:15:24.921322 | controller | skipping: Conditional result was False
2025-10-04 00:15:24.929606 | 
2025-10-04 00:15:24.929726 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-04 00:15:25.271234 | controller | ok: "logs"
2025-10-04 00:15:25.271541 | controller | ok: All items complete
2025-10-04 00:15:25.271584 | 
2025-10-04 00:15:25.559568 | controller | ok: "artifacts"
2025-10-04 00:15:25.857168 | controller | ok: "docs"
2025-10-04 00:15:25.878706 | 
2025-10-04 00:15:25.878877 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-04 00:15:26.221636 | controller | changed: "logs"
2025-10-04 00:15:26.506774 | controller | changed: "artifacts"
2025-10-04 00:15:26.793567 | controller | changed: "docs"
2025-10-04 00:15:26.942025 | 
2025-10-04 00:15:26.942115 | PLAY RECAP
2025-10-04 00:15:26.942166 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-04 00:15:26.942295 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-04 00:15:26.942324 | 
2025-10-04 00:15:27.078280 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-04 00:15:27.079187 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-04 00:15:27.721208 | 
2025-10-04 00:15:27.721333 | PLAY [all]
2025-10-04 00:15:27.751577 | 
2025-10-04 00:15:27.751735 | TASK [Install binary dependencies]
2025-10-04 00:15:27.802635 | controller | ok
2025-10-04 00:15:27.826569 | 
2025-10-04 00:15:27.826746 | TASK [bindep : Include find tasks]
2025-10-04 00:15:27.859783 | controller | ok
2025-10-04 00:15:27.871501 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-04 00:15:27.882542 | 
2025-10-04 00:15:27.882693 | TASK [bindep : Look for bindep.txt]
2025-10-04 00:15:28.393878 | controller | ok
2025-10-04 00:15:28.401039 | 
2025-10-04 00:15:28.401141 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:15:28.415595 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.423071 | 
2025-10-04 00:15:28.423154 | TASK [bindep : Look for other-requirements.txt]
2025-10-04 00:15:28.715220 | controller | ok
2025-10-04 00:15:28.727163 | 
2025-10-04 00:15:28.727307 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:15:28.755461 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.770720 | 
2025-10-04 00:15:28.770900 | TASK [bindep : Look for bindep fallback file]
2025-10-04 00:15:28.811729 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.824814 | 
2025-10-04 00:15:28.825379 | TASK [bindep : Define bindep_file fact]
2025-10-04 00:15:28.869219 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.881602 | 
2025-10-04 00:15:28.881974 | TASK [bindep : Include bindep tasks]
2025-10-04 00:15:28.921823 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.933013 | 
2025-10-04 00:15:28.933292 | TASK [bindep : Include install tasks]
2025-10-04 00:15:28.958256 | controller | skipping: Conditional result was False
2025-10-04 00:15:28.967372 | 
2025-10-04 00:15:28.967500 | LOOP [bindep : Include package tasks]
2025-10-04 00:15:29.040552 | 
2025-10-04 00:15:29.040803 | TASK [Run test-setup role]
2025-10-04 00:15:29.063646 | controller | ok
2025-10-04 00:15:29.091172 | 
2025-10-04 00:15:29.091349 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-04 00:15:29.393865 | controller | ok
2025-10-04 00:15:29.408183 | 
2025-10-04 00:15:29.408376 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-04 00:15:29.586193 | controller | skipping: Conditional result was False
2025-10-04 00:15:29.639247 | 
2025-10-04 00:15:29.639407 | PLAY RECAP
2025-10-04 00:15:29.639652 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-04 00:15:29.639808 | 
2025-10-04 00:15:29.753844 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-04 00:15:29.755093 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-04 00:15:30.431146 | 
2025-10-04 00:15:30.431302 | PLAY [controller]
2025-10-04 00:15:30.461966 | 
2025-10-04 00:15:30.462124 | TASK [Create the /root directory]
2025-10-04 00:15:31.213470 | controller | ok
2025-10-04 00:15:31.228538 | 
2025-10-04 00:15:31.228887 | TASK [Install glibc-langpack-en]
2025-10-04 00:15:39.291217 | controller | ok: Nothing to do
2025-10-04 00:15:39.304388 | 
2025-10-04 00:15:39.304551 | TASK [Ensure controller directory exists]
2025-10-04 00:15:39.750392 | controller | changed
2025-10-04 00:15:39.757376 | 
2025-10-04 00:15:39.757534 | TASK [Install container runtime]
2025-10-04 00:15:39.817561 | controller | ok
2025-10-04 00:15:39.898346 | 
2025-10-04 00:15:39.898560 | LOOP [ensure-podman : Find distribution installation]
2025-10-04 00:15:39.952051 | controller | ok: "/var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-04 00:15:39.968126 | controller | included: /var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-04 00:15:39.978411 | 
2025-10-04 00:15:39.978568 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-04 00:16:53.493959 | controller | changed
2025-10-04 00:16:53.500542 | 
2025-10-04 00:16:53.500623 | TASK [ensure-podman : Fetch podman version]
2025-10-04 00:16:54.278526 | controller | Client:       Podman Engine
2025-10-04 00:16:54.278632 | controller | Version:      4.6.2
2025-10-04 00:16:54.278681 | controller | API Version:  4.6.2
2025-10-04 00:16:54.278720 | controller | Go Version:   go1.19.12
2025-10-04 00:16:54.278788 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-04 00:16:54.278832 | controller | OS/Arch:      linux/amd64
2025-10-04 00:16:54.633924 | controller | ok: Runtime: 0:00:00.226431
2025-10-04 00:16:54.651182 | 
2025-10-04 00:16:54.651394 | TASK [ensure-podman : Print podman version installed]
2025-10-04 00:16:54.696046 | Podman version: Client:       Podman Engine
2025-10-04 00:16:54.696323 | Version:      4.6.2
2025-10-04 00:16:54.696388 | API Version:  4.6.2
2025-10-04 00:16:54.696436 | Go Version:   go1.19.12
2025-10-04 00:16:54.696481 | Built:        Mon Aug 28 19:38:31 2023
2025-10-04 00:16:54.696528 | OS/Arch:      linux/amd64
2025-10-04 00:16:54.711034 | 
2025-10-04 00:16:54.711201 | TASK [ensure-podman : Validate podman engine]
2025-10-04 00:16:54.855432 | controller | skipping: Conditional result was False
2025-10-04 00:16:54.864946 | 
2025-10-04 00:16:54.865071 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-04 00:16:54.881085 | controller | skipping: Conditional result was False
2025-10-04 00:16:54.904327 | 
2025-10-04 00:16:54.904578 | TASK [Ensure python3.8 is present]
2025-10-04 00:16:54.921395 | controller | skipping: Conditional result was False
2025-10-04 00:16:54.928821 | 
2025-10-04 00:16:54.928911 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-04 00:16:54.951021 | controller | ok
2025-10-04 00:16:54.974655 | 
2025-10-04 00:16:54.974784 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-04 00:16:58.815441 | controller | ok: Nothing to do
2025-10-04 00:16:58.822174 | 
2025-10-04 00:16:58.822303 | TASK [our-ensure-python : Also install python3-devel]
2025-10-04 00:17:11.750124 | controller | changed
2025-10-04 00:17:11.765803 | 
2025-10-04 00:17:11.765935 | TASK [Run ensure-virtualenv role]
2025-10-04 00:17:11.788652 | controller | ok
2025-10-04 00:17:11.822181 | 
2025-10-04 00:17:11.822338 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-04 00:17:12.217558 | controller | /usr/bin/virtualenv
2025-10-04 00:17:12.468807 | controller | ok: Runtime: 0:00:00.003842
2025-10-04 00:17:12.477091 | 
2025-10-04 00:17:12.477257 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-04 00:17:12.504731 | controller | skipping: Conditional result was False
2025-10-04 00:17:12.505024 | controller | ok: All items complete
2025-10-04 00:17:12.505055 | 
2025-10-04 00:17:12.525195 | 
2025-10-04 00:17:12.525431 | TASK [Find the full path of the Python interpreter]
2025-10-04 00:17:13.017622 | controller | /usr/bin/python3
2025-10-04 00:17:13.225532 | controller | ok
2025-10-04 00:17:13.233530 | 
2025-10-04 00:17:13.233644 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-04 00:17:14.598717 | controller | created virtual environment CPython3.11.0.final.0-64 in 739ms
2025-10-04 00:17:14.650614 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-04 00:17:14.650664 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-10-04 00:17:14.650679 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-04 00:17:14.650697 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-04 00:17:14.884434 | controller | changed
2025-10-04 00:17:14.900807 | 
2025-10-04 00:17:14.901046 | TASK [Set selinux package]
2025-10-04 00:17:14.937254 | controller | ok
2025-10-04 00:17:14.947261 | 
2025-10-04 00:17:14.947373 | TASK [Set selinux package (Fedora)]
2025-10-04 00:17:15.010136 | controller | ok
2025-10-04 00:17:15.017782 | 
2025-10-04 00:17:15.017894 | TASK [Install selinux into virtualenv]
2025-10-04 00:17:17.657589 | controller | Collecting selinux-please-lie-to-me
2025-10-04 00:17:17.753353 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-04 00:17:18.293909 | controller | Collecting setuptools<50.0.0
2025-10-04 00:17:18.308103 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-04 00:17:18.442291 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.4 MB/s eta 0:00:00
2025-10-04 00:17:18.594397 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-04 00:17:18.594817 | controller |   Attempting uninstall: setuptools
2025-10-04 00:17:18.599849 | controller |     Found existing installation: setuptools 62.6.0
2025-10-04 00:17:18.713916 | controller |     Uninstalling setuptools-62.6.0:
2025-10-04 00:17:18.729289 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-04 00:17:19.513656 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-04 00:17:19.727347 | controller |
2025-10-04 00:17:19.918895 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-04 00:17:19.918948 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-04 00:17:20.219343 | controller | ok: Runtime: 0:00:04.428084
2025-10-04 00:17:20.228190 | 
2025-10-04 00:17:20.228391 | TASK [Install pytest-forked into virtualenv]
2025-10-04 00:17:21.427589 | controller | Collecting pytest-forked
2025-10-04 00:17:21.519070 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-04 00:17:21.577528 | controller | Collecting py
2025-10-04 00:17:21.591452 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-04 00:17:21.629181 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-10-04 00:17:21.801640 | controller | Collecting pytest>=3.10
2025-10-04 00:17:21.815486 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-04 00:17:21.884620 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.5 MB/s eta 0:00:00
2025-10-04 00:17:21.937067 | controller | Collecting iniconfig>=1
2025-10-04 00:17:21.950799 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-04 00:17:22.017435 | controller | Collecting packaging>=20
2025-10-04 00:17:22.031247 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-04 00:17:22.044402 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.5 MB/s eta 0:00:00
2025-10-04 00:17:22.092800 | controller | Collecting pluggy<2,>=1.5
2025-10-04 00:17:22.107260 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-04 00:17:22.181712 | controller | Collecting pygments>=2.7.2
2025-10-04 00:17:22.197126 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-04 00:17:22.337388 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 8.9 MB/s eta 0:00:00
2025-10-04 00:17:22.467830 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-04 00:17:24.760199 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-04 00:17:24.776118 | controller |
2025-10-04 00:17:24.950940 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-04 00:17:24.950988 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-04 00:17:25.390155 | controller | ok: Runtime: 0:00:04.243077
2025-10-04 00:17:25.403728 | 
2025-10-04 00:17:25.403907 | TASK [Update pip]
2025-10-04 00:17:26.571542 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-04 00:17:26.865881 | controller | Collecting pip
2025-10-04 00:17:26.971438 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-04 00:17:27.142724 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.7 MB/s eta 0:00:00
2025-10-04 00:17:27.293024 | controller | Installing collected packages: pip
2025-10-04 00:17:27.293477 | controller |   Attempting uninstall: pip
2025-10-04 00:17:27.297966 | controller |     Found existing installation: pip 22.2.2
2025-10-04 00:17:27.557878 | controller |     Uninstalling pip-22.2.2:
2025-10-04 00:17:27.587709 | controller |       Successfully uninstalled pip-22.2.2
2025-10-04 00:17:29.338747 | controller | Successfully installed pip-25.2
2025-10-04 00:17:30.063866 | controller | ok: Runtime: 0:00:03.553904
2025-10-04 00:17:30.070260 | 
2025-10-04 00:17:30.070331 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-04 00:17:30.614645 | controller | changed
2025-10-04 00:17:30.622127 | 
2025-10-04 00:17:30.622222 | TASK [Install ansible into virtualenv]
2025-10-04 00:17:31.678100 | controller | Processing ./src/github.com/ansible/ansible
2025-10-04 00:17:31.684556 | controller |   Installing build dependencies: started
2025-10-04 00:17:33.594709 | controller |   Installing build dependencies: finished with status 'done'
2025-10-04 00:17:35.132707 | controller |   Getting requirements to build wheel: started
2025-10-04 00:17:35.132770 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-04 00:17:36.055245 | controller |   Preparing metadata (pyproject.toml): started
2025-10-04 00:17:36.055298 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-04 00:17:36.057723 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-10-04 00:17:36.062482 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-04 00:17:36.267002 | controller | ERROR
2025-10-04 00:17:36.267291 | controller | {
2025-10-04 00:17:36.267351 | controller |   "delta": "0:00:05.150004",
2025-10-04 00:17:36.267396 | controller |   "end": "2025-10-04 00:17:36.206899",
2025-10-04 00:17:36.267434 | controller |   "msg": "non-zero return code",
2025-10-04 00:17:36.267485 | controller |   "rc": 1,
2025-10-04 00:17:36.267522 | controller |   "start": "2025-10-04 00:17:31.056895"
2025-10-04 00:17:36.267557 | controller | }
failure
2025-10-04 00:17:36.270727 | 
2025-10-04 00:17:36.271844 | PLAY RECAP
2025-10-04 00:17:36.271968 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-04 00:17:36.272017 | 
2025-10-04 00:17:36.453467 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-04 00:17:36.454772 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-04 00:17:37.185805 | 
2025-10-04 00:17:37.185988 | PLAY [all]
2025-10-04 00:17:37.218665 | 
2025-10-04 00:17:37.218871 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-04 00:17:38.038848 | controller | changed: non-zero return code
2025-10-04 00:17:38.049024 | 
2025-10-04 00:17:38.049134 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-04 00:17:38.082867 | controller | skipping: Conditional result was False
2025-10-04 00:17:38.093322 | 
2025-10-04 00:17:38.093486 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-04 00:17:38.173913 | 
2025-10-04 00:17:38.174127 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-04 00:17:38.195768 | 
2025-10-04 00:17:38.195999 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-04 00:17:38.222437 | controller | skipping: Conditional result was False
2025-10-04 00:17:38.228583 | 
2025-10-04 00:17:38.228665 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-04 00:17:38.259365 | 
2025-10-04 00:17:38.259518 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-04 00:17:38.283043 | controller | skipping: Conditional result was False
2025-10-04 00:17:38.289091 | 
2025-10-04 00:17:38.289159 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-04 00:17:38.302137 | controller | skipping: Conditional result was False
2025-10-04 00:17:38.308318 | 
2025-10-04 00:17:38.308397 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-04 00:17:38.322625 | controller | skipping: Conditional result was False
2025-10-04 00:17:38.348518 | 
2025-10-04 00:17:38.348616 | PLAY RECAP
2025-10-04 00:17:38.348659 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-04 00:17:38.348703 | 
2025-10-04 00:17:38.469505 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-04 00:17:38.471438 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-04 00:17:39.167604 | 
2025-10-04 00:17:39.167756 | PLAY [all:!appliance*]
2025-10-04 00:17:39.201993 | 
2025-10-04 00:17:39.202125 | TASK [unregister the node]
2025-10-04 00:17:39.327600 | controller | skipping: Conditional result was False
2025-10-04 00:17:39.335154 | 
2025-10-04 00:17:39.335308 | TASK [include_role : fetch-output]
2025-10-04 00:17:39.365519 | controller | ok
2025-10-04 00:17:39.386757 | 
2025-10-04 00:17:39.386904 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-04 00:17:39.463564 | controller | skipping: Conditional result was False
2025-10-04 00:17:39.473243 | 
2025-10-04 00:17:39.473388 | TASK [fetch-output : Set log path for single node]
2025-10-04 00:17:39.515081 | controller | ok
2025-10-04 00:17:39.521076 | 
2025-10-04 00:17:39.521154 | LOOP [fetch-output : Ensure local output dirs]
2025-10-04 00:17:39.944113 | controller -> localhost | ok: "/var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/logs"
2025-10-04 00:17:40.251462 | controller -> localhost | changed: "/var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/artifacts"
2025-10-04 00:17:40.536625 | controller -> localhost | changed: "/var/lib/zuul/builds/2482680b41084a73b6ccfca84548e7eb/work/docs"
2025-10-04 00:17:40.554552 | 
2025-10-04 00:17:40.554793 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-04 00:17:41.833186 | controller | changed:
2025-10-04 00:17:41.833454 | controller | .d..t...... ./
2025-10-04 00:17:41.833505 | controller | cd+++++++++ controller/
2025-10-04 00:17:41.833566 | controller | changed: All items complete
2025-10-04 00:17:41.833598 | 
2025-10-04 00:17:42.877557 | controller | changed: .d..t...... ./
2025-10-04 00:17:43.906255 | controller | changed: .d..t...... ./
2025-10-04 00:17:43.930257 | 
2025-10-04 00:17:43.930386 | TASK [include_role : fetch-output-openshift]
2025-10-04 00:17:43.965961 | controller | skipping: Conditional result was False
2025-10-04 00:17:43.972949 | 
2025-10-04 00:17:43.973023 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-04 00:17:44.013698 | controller | skipping: Conditional result was False
2025-10-04 00:17:44.029586 | controller | skipping: Conditional result was False
2025-10-04 00:17:44.065602 | 
2025-10-04 00:17:44.065741 | PLAY [localhost]
2025-10-04 00:17:44.078745 | 
2025-10-04 00:17:44.078816 | TASK [Run Zuul manifest role]
2025-10-04 00:17:44.099743 | localhost | ok
2025-10-04 00:17:44.121222 | 
2025-10-04 00:17:44.121370 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-04 00:17:44.601244 | localhost | changed
2025-10-04 00:17:44.606781 | 
2025-10-04 00:17:44.606857 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-04 00:17:44.637127 | localhost | ok
2025-10-04 00:17:44.645953 | 
2025-10-04 00:17:44.646037 | TASK [Set zuul-log-path fact]
2025-10-04 00:17:44.675963 | localhost | ok
2025-10-04 00:17:44.695074 | 
2025-10-04 00:17:44.695435 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-04 00:17:44.728220 | localhost | ok
2025-10-04 00:17:44.740749 | 
2025-10-04 00:17:44.740889 | LOOP [Run upload-logs-swift role]
2025-10-04 00:17:44.778425 | localhost | Output suppressed because no_log was given
2025-10-04 00:17:44.819340 | 
2025-10-04 00:17:44.819499 | TASK [Set zuul-log-path fact]
2025-10-04 00:17:44.846021 | localhost | skipping: Conditional result was False
2025-10-04 00:17:44.853236 | 
2025-10-04 00:17:44.853356 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-04 00:17:45.293230 | localhost -> localhost | ok: Runtime: 0:00:00.005330
2025-10-04 00:17:45.299468 | 
2025-10-04 00:17:45.299588 | TASK [upload-logs-swift : Upload logs to swift]