2025-09-20 00:06:37.567788 | Job console starting...
2025-09-20 00:06:37.583262 | Updating repositories
2025-09-20 00:06:40.102849 | Preparing job workspace
2025-09-20 00:06:44.611372 | Running Ansible setup...
2025-09-20 00:06:50.818545 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-20 00:06:51.478155 | 
2025-09-20 00:06:51.478295 | PLAY [localhost]
2025-09-20 00:06:51.486905 | 
2025-09-20 00:06:51.486994 | TASK [Gathering Facts]
2025-09-20 00:06:52.442238 | localhost | ok
2025-09-20 00:06:52.474348 | 
2025-09-20 00:06:52.474523 | TASK [Setup log path fact]
2025-09-20 00:06:52.498514 | localhost | ok
2025-09-20 00:06:52.516206 | 
2025-09-20 00:06:52.516299 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-20 00:06:52.559457 | localhost | ok
2025-09-20 00:06:52.570754 | 
2025-09-20 00:06:52.570849 | TASK [emit-job-header : Print job information]
2025-09-20 00:06:52.627479 | # Job Information
2025-09-20 00:06:52.627844 | Ansible Version: 2.15.12
2025-09-20 00:06:52.627928 | Job: ansible-test-sanity-docker-milestone
2025-09-20 00:06:52.627988 | Pipeline: periodic
2025-09-20 00:06:52.628091 | Executor: ze01.softwarefactory-project.io
2025-09-20 00:06:52.628148 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-20 00:06:52.628206 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fa4/ansible/fa4f410adade423b98165b725026392d/
2025-09-20 00:06:52.628261 | Event ID: ea09755ff46b4297acaaa5c934db2f81
2025-09-20 00:06:52.638249 | 
2025-09-20 00:06:52.638413 | LOOP [emit-job-header : Print node information]
2025-09-20 00:06:52.752116 | localhost | ok:
2025-09-20 00:06:52.752377 | localhost | # Node Information
2025-09-20 00:06:52.752404 | localhost | Inventory Hostname: controller
2025-09-20 00:06:52.752424 | localhost | Hostname: ip-172-16-104-127
2025-09-20 00:06:52.752443 | localhost | Username: zuul-worker
2025-09-20 00:06:52.752463 | localhost | Distro: Fedora 37
2025-09-20 00:06:52.752482 | localhost | Provider: ansible-us-east-2
2025-09-20 00:06:52.752499 | localhost | Region: us-east-2
2025-09-20 00:06:52.752516 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-20 00:06:52.752533 | localhost | Product Name: t3.small
2025-09-20 00:06:52.752550 | localhost | Interface IP: 3.15.204.3
2025-09-20 00:06:52.775642 | 
2025-09-20 00:06:52.775870 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-20 00:06:53.299309 | localhost -> localhost | changed
2025-09-20 00:06:53.305538 | 
2025-09-20 00:06:53.305612 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-20 00:06:54.111076 | localhost -> localhost | changed
2025-09-20 00:06:54.130587 | 
2025-09-20 00:06:54.130963 | PLAY [all:!appliance*]
2025-09-20 00:06:54.145787 | 
2025-09-20 00:06:54.145853 | TASK [include_role : start-zuul-console]
2025-09-20 00:06:54.164623 | controller | ok
2025-09-20 00:06:54.177712 | 
2025-09-20 00:06:54.177778 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-20 00:06:54.849330 | controller | ok
2025-09-20 00:06:54.875127 | 
2025-09-20 00:06:54.875290 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-20 00:06:56.436238 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-20 00:06:56.450628 | 
2025-09-20 00:06:56.450782 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-20 00:06:56.608704 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.621817 | 
2025-09-20 00:06:56.621921 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-20 00:06:56.655749 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.670314 | 
2025-09-20 00:06:56.670502 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-20 00:06:56.708755 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.725373 | 
2025-09-20 00:06:56.725563 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-20 00:06:56.752267 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.762268 | 
2025-09-20 00:06:56.762404 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-20 00:06:56.789561 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.811377 | 
2025-09-20 00:06:56.811552 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-20 00:06:56.838758 | controller | skipping: Conditional result was False
2025-09-20 00:06:56.852422 | 
2025-09-20 00:06:56.852579 | TASK [Disable Fedora Modular]
2025-09-20 00:06:57.576355 | controller | changed
2025-09-20 00:06:57.585201 | 
2025-09-20 00:06:57.585348 | TASK [Enable EPEL]
2025-09-20 00:06:57.601377 | controller | skipping: Conditional result was False
2025-09-20 00:06:57.611876 | 
2025-09-20 00:06:57.612078 | TASK [Register the RHEL node]
2025-09-20 00:06:57.774294 | 
2025-09-20 00:06:57.774822 | TASK [Show the subscription-manager status]
2025-09-20 00:06:57.929791 | controller | skipping: Conditional result was False
2025-09-20 00:06:57.991191 | 
2025-09-20 00:06:57.991348 | TASK [Enable EPEL on RHEL]
2025-09-20 00:06:58.120705 | controller | skipping: Conditional result was False
2025-09-20 00:06:58.130765 | 
2025-09-20 00:06:58.130939 | TASK [Install git and tox]
2025-09-20 00:08:30.461827 | controller | changed
2025-09-20 00:08:30.476680 | 
2025-09-20 00:08:30.476822 | TASK [include_role : prepare-workspace]
2025-09-20 00:08:30.514827 | controller | ok
2025-09-20 00:08:30.548820 | 
2025-09-20 00:08:30.548967 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-20 00:08:31.069453 | controller | ok
2025-09-20 00:08:31.082941 | 
2025-09-20 00:08:31.083133 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-20 00:08:43.810180 | controller | Output suppressed because no_log was given
2025-09-20 00:08:43.825793 | 
2025-09-20 00:08:43.825886 | TASK [include_role : prepare-workspace-openshift]
2025-09-20 00:08:43.851898 | controller | skipping: Conditional result was False
2025-09-20 00:08:43.883981 | 
2025-09-20 00:08:43.884115 | PLAY [all:!appliance]
2025-09-20 00:08:43.906141 | 
2025-09-20 00:08:43.906233 | TASK [Run add-build-sshkey role (RSA)]
2025-09-20 00:08:44.007957 | controller | ok
2025-09-20 00:08:44.033675 | 
2025-09-20 00:08:44.033926 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-20 00:08:44.305367 | controller -> localhost | ok
2025-09-20 00:08:44.315945 | 
2025-09-20 00:08:44.316087 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-20 00:08:44.364273 | controller | ok
2025-09-20 00:08:44.383471 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-20 00:08:44.390241 | 
2025-09-20 00:08:44.390312 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-20 00:08:44.907779 | controller -> localhost | Generating public/private rsa key pair.
2025-09-20 00:08:44.908274 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_rsa.
2025-09-20 00:08:44.908350 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_rsa.pub.
2025-09-20 00:08:44.908402 | controller -> localhost | The key fingerprint is:
2025-09-20 00:08:44.908449 | controller -> localhost | SHA256:worTqpxbm3yQsmIif5y3um4KShjsOOkpcTtgE9h80Q4 zuul-build-sshkey
2025-09-20 00:08:44.908494 | controller -> localhost | The key's randomart image is:
2025-09-20 00:08:44.908538 | controller -> localhost | +---[RSA 2048]----+
2025-09-20 00:08:44.908581 | controller -> localhost | |     .           |
2025-09-20 00:08:44.908633 | controller -> localhost | |    E .          |
2025-09-20 00:08:44.908677 | controller -> localhost | |.o   +           |
2025-09-20 00:08:44.908720 | controller -> localhost | |o.o ...          |
2025-09-20 00:08:44.908762 | controller -> localhost | |..... o S        |
2025-09-20 00:08:44.908836 | controller -> localhost | |**.= . .         |
2025-09-20 00:08:44.908906 | controller -> localhost | |B**++.           |
2025-09-20 00:08:44.908953 | controller -> localhost | |X=BoB..          |
2025-09-20 00:08:44.909001 | controller -> localhost | |OO=X=+..         |
2025-09-20 00:08:44.909107 | controller -> localhost | +----[SHA256]-----+
2025-09-20 00:08:44.909224 | controller -> localhost | ok: Runtime: 0:00:00.107179
2025-09-20 00:08:44.924749 | 
2025-09-20 00:08:44.924891 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-20 00:08:44.965200 | controller | ok
2025-09-20 00:08:44.988163 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-20 00:08:45.001455 | 
2025-09-20 00:08:45.001543 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-20 00:08:45.037203 | controller | skipping: Conditional result was False
2025-09-20 00:08:45.047315 | 
2025-09-20 00:08:45.047423 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-20 00:08:45.687312 | controller | changed
2025-09-20 00:08:45.696420 | 
2025-09-20 00:08:45.696511 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-20 00:08:46.040383 | controller | ok
2025-09-20 00:08:46.053173 | 
2025-09-20 00:08:46.053339 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-20 00:08:47.361780 | controller | changed
2025-09-20 00:08:47.370223 | 
2025-09-20 00:08:47.370408 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-20 00:08:48.625050 | controller | changed
2025-09-20 00:08:48.638952 | 
2025-09-20 00:08:48.639156 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-20 00:08:48.668708 | controller | skipping: Conditional result was False
2025-09-20 00:08:48.683441 | 
2025-09-20 00:08:48.683612 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-20 00:08:49.098648 | controller -> localhost | changed
2025-09-20 00:08:49.110185 | 
2025-09-20 00:08:49.110268 | TASK [add-build-sshkey : Add back temp key]
2025-09-20 00:08:49.503153 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_rsa (zuul-build-sshkey)
2025-09-20 00:08:49.503602 | controller -> localhost | ok: Runtime: 0:00:00.008123
2025-09-20 00:08:49.517754 | 
2025-09-20 00:08:49.517893 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-20 00:08:50.081791 | controller | ok
2025-09-20 00:08:50.093806 | 
2025-09-20 00:08:50.093945 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-20 00:08:50.132231 | controller | skipping: Conditional result was False
2025-09-20 00:08:50.160053 | 
2025-09-20 00:08:50.160211 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-20 00:08:50.198114 | controller | ok
2025-09-20 00:08:50.226846 | 
2025-09-20 00:08:50.226971 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-20 00:08:50.552548 | controller -> localhost | ok
2025-09-20 00:08:50.567261 | 
2025-09-20 00:08:50.567427 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-20 00:08:50.623672 | controller | ok
2025-09-20 00:08:50.651266 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-20 00:08:50.661553 | 
2025-09-20 00:08:50.661687 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-20 00:08:50.995307 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-20 00:08:50.995581 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_ecdsa.
2025-09-20 00:08:50.995611 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_ecdsa.pub.
2025-09-20 00:08:50.995645 | controller -> localhost | The key fingerprint is:
2025-09-20 00:08:50.995666 | controller -> localhost | SHA256:OMYL8TstmrIDCmwzoZLolxS6luFHiGwy8+RlwpfKvM4 zuul-build-sshkey
2025-09-20 00:08:50.995685 | controller -> localhost | The key's randomart image is:
2025-09-20 00:08:50.995703 | controller -> localhost | +---[ECDSA 521]---+
2025-09-20 00:08:50.995721 | controller -> localhost | |                 |
2025-09-20 00:08:50.995738 | controller -> localhost | |                 |
2025-09-20 00:08:50.995756 | controller -> localhost | |    .            |
2025-09-20 00:08:50.995773 | controller -> localhost | | . . + .         |
2025-09-20 00:08:50.995791 | controller -> localhost | |*o+ o.* S        |
2025-09-20 00:08:50.995808 | controller -> localhost | |%@+o=o =         |
2025-09-20 00:08:50.995826 | controller -> localhost | |XXO*. = .        |
2025-09-20 00:08:50.995843 | controller -> localhost | |.BO+ o o         |
2025-09-20 00:08:50.995860 | controller -> localhost | |..E=o            |
2025-09-20 00:08:50.995877 | controller -> localhost | +----[SHA256]-----+
2025-09-20 00:08:50.995934 | controller -> localhost | ok: Runtime: 0:00:00.016258
2025-09-20 00:08:51.003420 | 
2025-09-20 00:08:51.003505 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-20 00:08:51.045340 | controller | ok
2025-09-20 00:08:51.053133 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-20 00:08:51.062521 | 
2025-09-20 00:08:51.062602 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-20 00:08:51.097978 | controller | skipping: Conditional result was False
2025-09-20 00:08:51.105396 | 
2025-09-20 00:08:51.105520 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-20 00:08:51.552178 | controller | changed
2025-09-20 00:08:51.558143 | 
2025-09-20 00:08:51.558221 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-20 00:08:51.899314 | controller | ok
2025-09-20 00:08:51.912240 | 
2025-09-20 00:08:51.912373 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-20 00:08:53.122282 | controller | changed
2025-09-20 00:08:53.135414 | 
2025-09-20 00:08:53.135632 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-20 00:08:54.394888 | controller | changed
2025-09-20 00:08:54.408423 | 
2025-09-20 00:08:54.408639 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-20 00:08:54.447650 | controller | skipping: Conditional result was False
2025-09-20 00:08:54.463153 | 
2025-09-20 00:08:54.463376 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-20 00:08:54.793993 | controller -> localhost | changed
2025-09-20 00:08:54.806132 | 
2025-09-20 00:08:54.806260 | TASK [add-build-sshkey : Add back temp key]
2025-09-20 00:08:55.162009 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/fa4f410adade423b98165b725026392d_id_ecdsa (zuul-build-sshkey)
2025-09-20 00:08:55.162351 | controller -> localhost | ok: Runtime: 0:00:00.011154
2025-09-20 00:08:55.172543 | 
2025-09-20 00:08:55.172712 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-20 00:08:55.507849 | controller | ok
2025-09-20 00:08:55.516543 | 
2025-09-20 00:08:55.516688 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-20 00:08:55.543401 | controller | skipping: Conditional result was False
2025-09-20 00:08:55.562388 | 
2025-09-20 00:08:55.562558 | TASK [include_role : remove-zuul-sshkey]
2025-09-20 00:08:55.589146 | controller | skipping: Conditional result was False
2025-09-20 00:08:55.599091 | 
2025-09-20 00:08:55.599268 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-20 00:08:56.043663 | controller | ok: "logs"
2025-09-20 00:08:56.043925 | controller | ok: All items complete
2025-09-20 00:08:56.043966 | 
2025-09-20 00:08:56.268373 | controller | ok: "artifacts"
2025-09-20 00:08:56.552884 | controller | ok: "docs"
2025-09-20 00:08:56.569222 | 
2025-09-20 00:08:56.569433 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-20 00:08:56.908150 | controller | changed: "logs"
2025-09-20 00:08:57.196879 | controller | changed: "artifacts"
2025-09-20 00:08:57.483092 | controller | changed: "docs"
2025-09-20 00:08:57.539363 | 
2025-09-20 00:08:57.539499 | PLAY RECAP
2025-09-20 00:08:57.539554 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-20 00:08:57.539588 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-20 00:08:57.539613 | 
2025-09-20 00:08:57.696684 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-20 00:08:57.698561 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-20 00:08:58.303953 | 
2025-09-20 00:08:58.304090 | PLAY [all]
2025-09-20 00:08:58.327859 | 
2025-09-20 00:08:58.327998 | TASK [Install binary dependencies]
2025-09-20 00:08:58.399705 | controller | ok
2025-09-20 00:08:58.420842 | 
2025-09-20 00:08:58.420984 | TASK [bindep : Include find tasks]
2025-09-20 00:08:58.450787 | controller | ok
2025-09-20 00:08:58.458636 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-20 00:08:58.464850 | 
2025-09-20 00:08:58.464916 | TASK [bindep : Look for bindep.txt]
2025-09-20 00:08:58.989534 | controller | ok
2025-09-20 00:08:58.998802 | 
2025-09-20 00:08:58.998939 | TASK [bindep : Define bindep_file fact]
2025-09-20 00:08:59.029080 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.042915 | 
2025-09-20 00:08:59.043158 | TASK [bindep : Look for other-requirements.txt]
2025-09-20 00:08:59.357083 | controller | ok
2025-09-20 00:08:59.370145 | 
2025-09-20 00:08:59.370338 | TASK [bindep : Define bindep_file fact]
2025-09-20 00:08:59.398723 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.414171 | 
2025-09-20 00:08:59.414393 | TASK [bindep : Look for bindep fallback file]
2025-09-20 00:08:59.442374 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.455386 | 
2025-09-20 00:08:59.455543 | TASK [bindep : Define bindep_file fact]
2025-09-20 00:08:59.483060 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.496698 | 
2025-09-20 00:08:59.496861 | TASK [bindep : Include bindep tasks]
2025-09-20 00:08:59.524770 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.542874 | 
2025-09-20 00:08:59.543078 | TASK [bindep : Include install tasks]
2025-09-20 00:08:59.570615 | controller | skipping: Conditional result was False
2025-09-20 00:08:59.585152 | 
2025-09-20 00:08:59.585320 | LOOP [bindep : Include package tasks]
2025-09-20 00:08:59.671545 | 
2025-09-20 00:08:59.671847 | TASK [Run test-setup role]
2025-09-20 00:08:59.701316 | controller | ok
2025-09-20 00:08:59.732452 | 
2025-09-20 00:08:59.732610 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-20 00:09:00.046880 | controller | ok
2025-09-20 00:09:00.060608 | 
2025-09-20 00:09:00.060746 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-20 00:09:00.212747 | controller | skipping: Conditional result was False
2025-09-20 00:09:00.250111 | 
2025-09-20 00:09:00.250246 | PLAY RECAP
2025-09-20 00:09:00.250319 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-20 00:09:00.250359 | 
2025-09-20 00:09:00.377388 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-20 00:09:00.379974 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-20 00:09:01.063771 | 
2025-09-20 00:09:01.063927 | PLAY [controller]
2025-09-20 00:09:01.083263 | 
2025-09-20 00:09:01.083350 | TASK [Create the /root directory]
2025-09-20 00:09:01.910089 | controller | ok
2025-09-20 00:09:01.923575 | 
2025-09-20 00:09:01.923777 | TASK [Install glibc-langpack-en]
2025-09-20 00:09:10.347866 | controller | ok: Nothing to do
2025-09-20 00:09:10.361357 | 
2025-09-20 00:09:10.361569 | TASK [Ensure controller directory exists]
2025-09-20 00:09:10.774750 | controller | changed
2025-09-20 00:09:10.788111 | 
2025-09-20 00:09:10.788265 | TASK [Install container runtime]
2025-09-20 00:09:10.872991 | controller | ok
2025-09-20 00:09:10.937436 | 
2025-09-20 00:09:10.937575 | LOOP [ensure-podman : Find distribution installation]
2025-09-20 00:09:10.983214 | controller | ok: "/var/lib/zuul/builds/fa4f410adade423b98165b725026392d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-20 00:09:11.008633 | controller | included: /var/lib/zuul/builds/fa4f410adade423b98165b725026392d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-20 00:09:11.015739 | 
2025-09-20 00:09:11.015809 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-20 00:10:27.918658 | controller | changed
2025-09-20 00:10:27.932544 | 
2025-09-20 00:10:27.932676 | TASK [ensure-podman : Fetch podman version]
2025-09-20 00:10:28.719955 | controller | Client:       Podman Engine
2025-09-20 00:10:28.720088 | controller | Version:      4.6.2
2025-09-20 00:10:28.720134 | controller | API Version:  4.6.2
2025-09-20 00:10:28.720175 | controller | Go Version:   go1.19.12
2025-09-20 00:10:28.720230 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-20 00:10:28.720283 | controller | OS/Arch:      linux/amd64
2025-09-20 00:10:29.099815 | controller | ok: Runtime: 0:00:00.224919
2025-09-20 00:10:29.121565 | 
2025-09-20 00:10:29.121807 | TASK [ensure-podman : Print podman version installed]
2025-09-20 00:10:29.163862 | Podman version: Client:       Podman Engine
2025-09-20 00:10:29.164217 | Version:      4.6.2
2025-09-20 00:10:29.164313 | API Version:  4.6.2
2025-09-20 00:10:29.164393 | Go Version:   go1.19.12
2025-09-20 00:10:29.164447 | Built:        Mon Aug 28 19:38:31 2023
2025-09-20 00:10:29.164494 | OS/Arch:      linux/amd64
2025-09-20 00:10:29.176834 | 
2025-09-20 00:10:29.176962 | TASK [ensure-podman : Validate podman engine]
2025-09-20 00:10:29.313918 | controller | skipping: Conditional result was False
2025-09-20 00:10:29.323048 | 
2025-09-20 00:10:29.323703 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-20 00:10:29.350667 | controller | skipping: Conditional result was False
2025-09-20 00:10:29.365635 | 
2025-09-20 00:10:29.365726 | TASK [Ensure python3.8 is present]
2025-09-20 00:10:29.391576 | controller | skipping: Conditional result was False
2025-09-20 00:10:29.399185 | 
2025-09-20 00:10:29.399390 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-20 00:10:29.423348 | controller | ok
2025-09-20 00:10:29.450925 | 
2025-09-20 00:10:29.451066 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-20 00:10:33.381233 | controller | ok: Nothing to do
2025-09-20 00:10:33.392791 | 
2025-09-20 00:10:33.392922 | TASK [our-ensure-python : Also install python3-devel]
2025-09-20 00:10:47.024007 | controller | changed
2025-09-20 00:10:47.047218 | 
2025-09-20 00:10:47.047431 | TASK [Run ensure-virtualenv role]
2025-09-20 00:10:47.073155 | controller | ok
2025-09-20 00:10:47.101223 | 
2025-09-20 00:10:47.101440 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-20 00:10:47.470005 | controller | /usr/bin/virtualenv
2025-09-20 00:10:47.735901 | controller | ok: Runtime: 0:00:00.004557
2025-09-20 00:10:47.744523 | 
2025-09-20 00:10:47.744636 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-20 00:10:47.800947 | controller | skipping: Conditional result was False
2025-09-20 00:10:47.801529 | controller | ok: All items complete
2025-09-20 00:10:47.801595 | 
2025-09-20 00:10:47.873445 | 
2025-09-20 00:10:47.873607 | TASK [Find the full path of the Python interpreter]
2025-09-20 00:10:48.285781 | controller | /usr/bin/python3
2025-09-20 00:10:48.507628 | controller | ok
2025-09-20 00:10:48.516514 | 
2025-09-20 00:10:48.516677 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-20 00:10:49.935137 | controller | created virtual environment CPython3.11.0.final.0-64 in 778ms
2025-09-20 00:10:49.971484 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-20 00:10:49.971533 | 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-09-20 00:10:49.971545 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-20 00:10:49.971561 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-20 00:10:50.163608 | controller | changed
2025-09-20 00:10:50.172611 | 
2025-09-20 00:10:50.172791 | TASK [Set selinux package]
2025-09-20 00:10:50.211442 | controller | ok
2025-09-20 00:10:50.224244 | 
2025-09-20 00:10:50.224408 | TASK [Set selinux package (Fedora)]
2025-09-20 00:10:50.287157 | controller | ok
2025-09-20 00:10:50.300509 | 
2025-09-20 00:10:50.300708 | TASK [Install selinux into virtualenv]
2025-09-20 00:10:53.565541 | controller | Collecting selinux-please-lie-to-me
2025-09-20 00:10:53.653810 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-20 00:10:54.185424 | controller | Collecting setuptools<50.0.0
2025-09-20 00:10:54.197973 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-20 00:10:54.331501 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.4 MB/s eta 0:00:00
2025-09-20 00:10:54.487159 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-20 00:10:54.487479 | controller |   Attempting uninstall: setuptools
2025-09-20 00:10:54.492376 | controller |     Found existing installation: setuptools 62.6.0
2025-09-20 00:10:54.604624 | controller |     Uninstalling setuptools-62.6.0:
2025-09-20 00:10:54.619939 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-20 00:10:55.368791 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-20 00:10:55.575873 | controller |
2025-09-20 00:10:55.791273 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-20 00:10:55.791326 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-20 00:10:56.056154 | controller | ok: Runtime: 0:00:04.395373
2025-09-20 00:10:56.065849 | 
2025-09-20 00:10:56.066004 | TASK [Install pytest-forked into virtualenv]
2025-09-20 00:10:57.257765 | controller | Collecting pytest-forked
2025-09-20 00:10:57.345834 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-20 00:10:57.403580 | controller | Collecting py
2025-09-20 00:10:57.417126 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-20 00:10:57.453150 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-09-20 00:10:57.629984 | controller | Collecting pytest>=3.10
2025-09-20 00:10:57.643378 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-20 00:10:57.707889 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-09-20 00:10:57.761493 | controller | Collecting iniconfig>=1
2025-09-20 00:10:57.775038 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-20 00:10:57.850497 | controller | Collecting packaging>=20
2025-09-20 00:10:57.863931 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-20 00:10:57.876139 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00
2025-09-20 00:10:57.921949 | controller | Collecting pluggy<2,>=1.5
2025-09-20 00:10:57.935020 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-20 00:10:58.006963 | controller | Collecting pygments>=2.7.2
2025-09-20 00:10:58.020363 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-20 00:10:58.150222 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.6 MB/s eta 0:00:00
2025-09-20 00:10:58.284645 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-20 00:11:00.547495 | 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-09-20 00:11:00.563599 | controller |
2025-09-20 00:11:00.753921 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-20 00:11:00.753966 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-20 00:11:01.219835 | controller | ok: Runtime: 0:00:04.219698
2025-09-20 00:11:01.233696 | 
2025-09-20 00:11:01.234132 | TASK [Update pip]
2025-09-20 00:11:02.333250 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-20 00:11:02.610304 | controller | Collecting pip
2025-09-20 00:11:02.697812 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-20 00:11:02.892913 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.3 MB/s eta 0:00:00
2025-09-20 00:11:03.039552 | controller | Installing collected packages: pip
2025-09-20 00:11:03.039991 | controller |   Attempting uninstall: pip
2025-09-20 00:11:03.044613 | controller |     Found existing installation: pip 22.2.2
2025-09-20 00:11:03.319205 | controller |     Uninstalling pip-22.2.2:
2025-09-20 00:11:03.360362 | controller |       Successfully uninstalled pip-22.2.2
2025-09-20 00:11:05.144320 | controller | Successfully installed pip-25.2
2025-09-20 00:11:05.436753 | controller | ok: Runtime: 0:00:03.636290
2025-09-20 00:11:05.449254 | 
2025-09-20 00:11:05.449389 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-20 00:11:05.967349 | controller | changed
2025-09-20 00:11:05.979196 | 
2025-09-20 00:11:05.979325 | TASK [Install ansible into virtualenv]
2025-09-20 00:11:07.048285 | controller | Processing ./src/github.com/ansible/ansible
2025-09-20 00:11:07.054832 | controller |   Installing build dependencies: started
2025-09-20 00:11:08.958305 | controller |   Installing build dependencies: finished with status 'done'
2025-09-20 00:11:10.485611 | controller |   Getting requirements to build wheel: started
2025-09-20 00:11:10.485677 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-20 00:11:10.487081 | controller |   Preparing metadata (pyproject.toml): started
2025-09-20 00:11:11.416109 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-20 00:11:11.420343 | 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-09-20 00:11:11.420391 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-20 00:11:11.647547 | controller | ERROR
2025-09-20 00:11:11.647775 | controller | {
2025-09-20 00:11:11.647835 | controller |   "delta": "0:00:05.153553",
2025-09-20 00:11:11.647876 | controller |   "end": "2025-09-20 00:11:11.569463",
2025-09-20 00:11:11.647911 | controller |   "msg": "non-zero return code",
2025-09-20 00:11:11.647965 | controller |   "rc": 1,
2025-09-20 00:11:11.648001 | controller |   "start": "2025-09-20 00:11:06.415910"
2025-09-20 00:11:11.648082 | controller | }
failure
2025-09-20 00:11:11.650433 | 
2025-09-20 00:11:11.650538 | PLAY RECAP
2025-09-20 00:11:11.650629 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-20 00:11:11.650682 | 
2025-09-20 00:11:11.779269 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-20 00:11:11.781224 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-20 00:11:12.420226 | 
2025-09-20 00:11:12.420341 | PLAY [all]
2025-09-20 00:11:12.442538 | 
2025-09-20 00:11:12.442630 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-20 00:11:13.206696 | controller | changed: non-zero return code
2025-09-20 00:11:13.214792 | 
2025-09-20 00:11:13.214905 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-20 00:11:13.243616 | controller | skipping: Conditional result was False
2025-09-20 00:11:13.258624 | 
2025-09-20 00:11:13.258760 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-20 00:11:13.294043 | 
2025-09-20 00:11:13.294247 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-20 00:11:13.328485 | 
2025-09-20 00:11:13.328691 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-20 00:11:13.345250 | controller | skipping: Conditional result was False
2025-09-20 00:11:13.356211 | 
2025-09-20 00:11:13.356335 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-20 00:11:13.382490 | 
2025-09-20 00:11:13.382704 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-20 00:11:13.408679 | controller | skipping: Conditional result was False
2025-09-20 00:11:13.417755 | 
2025-09-20 00:11:13.417847 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-20 00:11:13.443128 | controller | skipping: Conditional result was False
2025-09-20 00:11:13.452185 | 
2025-09-20 00:11:13.452287 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-20 00:11:13.478171 | controller | skipping: Conditional result was False
2025-09-20 00:11:13.513912 | 
2025-09-20 00:11:13.514037 | PLAY RECAP
2025-09-20 00:11:13.514096 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-20 00:11:13.514125 | 
2025-09-20 00:11:13.615650 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-20 00:11:13.616551 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-20 00:11:14.183657 | 
2025-09-20 00:11:14.183788 | PLAY [all:!appliance*]
2025-09-20 00:11:14.204782 | 
2025-09-20 00:11:14.204870 | TASK [unregister the node]
2025-09-20 00:11:14.335761 | controller | skipping: Conditional result was False
2025-09-20 00:11:14.342294 | 
2025-09-20 00:11:14.342377 | TASK [include_role : fetch-output]
2025-09-20 00:11:14.393200 | controller | ok
2025-09-20 00:11:14.413467 | 
2025-09-20 00:11:14.413552 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-20 00:11:14.490157 | controller | skipping: Conditional result was False
2025-09-20 00:11:14.496449 | 
2025-09-20 00:11:14.496524 | TASK [fetch-output : Set log path for single node]
2025-09-20 00:11:14.547953 | controller | ok
2025-09-20 00:11:14.553475 | 
2025-09-20 00:11:14.553537 | LOOP [fetch-output : Ensure local output dirs]
2025-09-20 00:11:15.096230 | controller -> localhost | ok: "/var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/logs"
2025-09-20 00:11:15.421895 | controller -> localhost | changed: "/var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/artifacts"
2025-09-20 00:11:15.740002 | controller -> localhost | changed: "/var/lib/zuul/builds/fa4f410adade423b98165b725026392d/work/docs"
2025-09-20 00:11:15.751158 | 
2025-09-20 00:11:15.751295 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-20 00:11:17.034083 | controller | changed:
2025-09-20 00:11:17.034336 | controller | .d..t...... ./
2025-09-20 00:11:17.034364 | controller | cd+++++++++ controller/
2025-09-20 00:11:17.034397 | controller | changed: All items complete
2025-09-20 00:11:17.034436 | 
2025-09-20 00:11:18.155887 | controller | changed: .d..t...... ./
2025-09-20 00:11:19.241326 | controller | changed: .d..t...... ./
2025-09-20 00:11:19.268632 | 
2025-09-20 00:11:19.268838 | TASK [include_role : fetch-output-openshift]
2025-09-20 00:11:19.297881 | controller | skipping: Conditional result was False
2025-09-20 00:11:19.313149 | 
2025-09-20 00:11:19.313296 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-20 00:11:19.361270 | controller | skipping: Conditional result was False
2025-09-20 00:11:19.377267 | controller | skipping: Conditional result was False
2025-09-20 00:11:19.435307 | 
2025-09-20 00:11:19.435448 | PLAY [localhost]
2025-09-20 00:11:19.453149 | 
2025-09-20 00:11:19.453235 | TASK [Run Zuul manifest role]
2025-09-20 00:11:19.475291 | localhost | ok
2025-09-20 00:11:19.494256 | 
2025-09-20 00:11:19.494349 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-20 00:11:19.939047 | localhost | changed
2025-09-20 00:11:19.950821 | 
2025-09-20 00:11:19.950975 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-20 00:11:19.991649 | localhost | ok
2025-09-20 00:11:20.009892 | 
2025-09-20 00:11:20.010058 | TASK [Set zuul-log-path fact]
2025-09-20 00:11:20.033796 | localhost | ok
2025-09-20 00:11:20.052724 | 
2025-09-20 00:11:20.052830 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-20 00:11:20.085336 | localhost | ok
2025-09-20 00:11:20.098260 | 
2025-09-20 00:11:20.098343 | LOOP [Run upload-logs-swift role]
2025-09-20 00:11:20.144999 | localhost | Output suppressed because no_log was given
2025-09-20 00:11:20.181104 | 
2025-09-20 00:11:20.181265 | TASK [Set zuul-log-path fact]
2025-09-20 00:11:20.207564 | localhost | skipping: Conditional result was False
2025-09-20 00:11:20.213587 | 
2025-09-20 00:11:20.213665 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-20 00:11:20.709006 | localhost -> localhost | ok: Runtime: 0:00:00.010737
2025-09-20 00:11:20.722993 | 
2025-09-20 00:11:20.723168 | TASK [upload-logs-swift : Upload logs to swift]