2025-10-01 00:06:38.549733 | Job console starting...
2025-10-01 00:06:38.563088 | Updating repositories
2025-10-01 00:06:38.716762 | Preparing job workspace
2025-10-01 00:06:42.431594 | Running Ansible setup...
2025-10-01 00:06:48.290289 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-01 00:06:48.998901 | 
2025-10-01 00:06:48.999061 | PLAY [localhost]
2025-10-01 00:06:49.007917 | 
2025-10-01 00:06:49.007997 | TASK [Gathering Facts]
2025-10-01 00:06:49.942129 | localhost | ok
2025-10-01 00:06:49.957466 | 
2025-10-01 00:06:49.957609 | TASK [Setup log path fact]
2025-10-01 00:06:49.976767 | localhost | ok
2025-10-01 00:06:50.001144 | 
2025-10-01 00:06:50.001435 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-01 00:06:50.036166 | localhost | ok
2025-10-01 00:06:50.053739 | 
2025-10-01 00:06:50.053891 | TASK [emit-job-header : Print job information]
2025-10-01 00:06:50.098294 | # Job Information
2025-10-01 00:06:50.098549 | Ansible Version: 2.15.12
2025-10-01 00:06:50.098622 | Job: ansible-test-sanity-docker-devel
2025-10-01 00:06:50.098707 | Pipeline: periodic
2025-10-01 00:06:50.098759 | Executor: ze02.softwarefactory-project.io
2025-10-01 00:06:50.098804 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-01 00:06:50.098857 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/098/ansible/09852676c7ba4fa78daa052840bbede8/
2025-10-01 00:06:50.098904 | Event ID: 2d247e7dd365484888695175254b0a86
2025-10-01 00:06:50.107546 | 
2025-10-01 00:06:50.107754 | LOOP [emit-job-header : Print node information]
2025-10-01 00:06:50.214189 | localhost | ok:
2025-10-01 00:06:50.214591 | localhost | # Node Information
2025-10-01 00:06:50.214625 | localhost | Inventory Hostname: controller
2025-10-01 00:06:50.214645 | localhost | Hostname: ip-172-16-184-102
2025-10-01 00:06:50.214677 | localhost | Username: zuul-worker
2025-10-01 00:06:50.214701 | localhost | Distro: Fedora 37
2025-10-01 00:06:50.214720 | localhost | Provider: ansible-us-east-2
2025-10-01 00:06:50.214737 | localhost | Region: us-east-2
2025-10-01 00:06:50.214753 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-01 00:06:50.214769 | localhost | Product Name: t3.small
2025-10-01 00:06:50.214785 | localhost | Interface IP: 18.188.53.80
2025-10-01 00:06:50.236231 | 
2025-10-01 00:06:50.236402 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-01 00:06:50.661618 | localhost -> localhost | changed
2025-10-01 00:06:50.667357 | 
2025-10-01 00:06:50.667454 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-01 00:06:51.671772 | localhost -> localhost | changed
2025-10-01 00:06:51.701177 | 
2025-10-01 00:06:51.701327 | PLAY [all:!appliance*]
2025-10-01 00:06:51.717906 | 
2025-10-01 00:06:51.717991 | TASK [include_role : start-zuul-console]
2025-10-01 00:06:51.738082 | controller | ok
2025-10-01 00:06:51.753187 | 
2025-10-01 00:06:51.753270 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-01 00:06:52.433270 | controller | ok
2025-10-01 00:06:52.459098 | 
2025-10-01 00:06:52.459266 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-01 00:06:54.478431 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-01 00:06:54.491943 | 
2025-10-01 00:06:54.492038 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-01 00:06:54.639520 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.649292 | 
2025-10-01 00:06:54.649402 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-01 00:06:54.676330 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.686108 | 
2025-10-01 00:06:54.686224 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-01 00:06:54.712602 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.727656 | 
2025-10-01 00:06:54.727842 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-01 00:06:54.766782 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.781623 | 
2025-10-01 00:06:54.781838 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-01 00:06:54.820453 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.830168 | 
2025-10-01 00:06:54.830312 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-01 00:06:54.866374 | controller | skipping: Conditional result was False
2025-10-01 00:06:54.883362 | 
2025-10-01 00:06:54.883455 | TASK [Disable Fedora Modular]
2025-10-01 00:06:55.606383 | controller | changed
2025-10-01 00:06:55.618950 | 
2025-10-01 00:06:55.619113 | TASK [Enable EPEL]
2025-10-01 00:06:55.648098 | controller | skipping: Conditional result was False
2025-10-01 00:06:55.662623 | 
2025-10-01 00:06:55.663012 | TASK [Register the RHEL node]
2025-10-01 00:06:55.845877 | 
2025-10-01 00:06:55.846319 | TASK [Show the subscription-manager status]
2025-10-01 00:06:56.048706 | controller | skipping: Conditional result was False
2025-10-01 00:06:56.062521 | 
2025-10-01 00:06:56.062757 | TASK [Enable EPEL on RHEL]
2025-10-01 00:06:56.216773 | controller | skipping: Conditional result was False
2025-10-01 00:06:56.231950 | 
2025-10-01 00:06:56.232136 | TASK [Install git and tox]
2025-10-01 00:08:21.878282 | controller | changed
2025-10-01 00:08:21.892641 | 
2025-10-01 00:08:21.893111 | TASK [include_role : prepare-workspace]
2025-10-01 00:08:21.932885 | controller | ok
2025-10-01 00:08:21.973236 | 
2025-10-01 00:08:21.973375 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-01 00:08:22.466366 | controller | ok
2025-10-01 00:08:22.473908 | 
2025-10-01 00:08:22.474009 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-01 00:08:36.366234 | controller | Output suppressed because no_log was given
2025-10-01 00:08:36.376610 | 
2025-10-01 00:08:36.376712 | TASK [include_role : prepare-workspace-openshift]
2025-10-01 00:08:36.394363 | controller | skipping: Conditional result was False
2025-10-01 00:08:36.471844 | 
2025-10-01 00:08:36.471967 | PLAY [all:!appliance]
2025-10-01 00:08:36.487489 | 
2025-10-01 00:08:36.487589 | TASK [Run add-build-sshkey role (RSA)]
2025-10-01 00:08:36.518202 | controller | ok
2025-10-01 00:08:36.534842 | 
2025-10-01 00:08:36.534973 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-01 00:08:36.792182 | controller -> localhost | ok
2025-10-01 00:08:36.799441 | 
2025-10-01 00:08:36.799521 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-01 00:08:36.831778 | controller | ok
2025-10-01 00:08:36.846826 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-01 00:08:36.852917 | 
2025-10-01 00:08:36.853004 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-01 00:08:37.354032 | controller -> localhost | Generating public/private rsa key pair.
2025-10-01 00:08:37.354305 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_rsa.
2025-10-01 00:08:37.354335 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_rsa.pub.
2025-10-01 00:08:37.354356 | controller -> localhost | The key fingerprint is:
2025-10-01 00:08:37.354375 | controller -> localhost | SHA256:yFl4t9zgZ7SdmwpWfMRq09d96o+yS1hXJcl1ofkAVkg zuul-build-sshkey
2025-10-01 00:08:37.354395 | controller -> localhost | The key's randomart image is:
2025-10-01 00:08:37.354414 | controller -> localhost | +---[RSA 2048]----+
2025-10-01 00:08:37.354431 | controller -> localhost | |          .Eoo.+=|
2025-10-01 00:08:37.354450 | controller -> localhost | |       .  ....=.o|
2025-10-01 00:08:37.354468 | controller -> localhost | |      . o o .+o .|
2025-10-01 00:08:37.354485 | controller -> localhost | |     . = + * *ooo|
2025-10-01 00:08:37.354503 | controller -> localhost | |      + S + % *.=|
2025-10-01 00:08:37.354531 | controller -> localhost | |           B + =.|
2025-10-01 00:08:37.354554 | controller -> localhost | |          + . +  |
2025-10-01 00:08:37.354574 | controller -> localhost | |         . o.o . |
2025-10-01 00:08:37.354592 | controller -> localhost | |            ++o..|
2025-10-01 00:08:37.354612 | controller -> localhost | +----[SHA256]-----+
2025-10-01 00:08:37.354692 | controller -> localhost | ok: Runtime: 0:00:00.138502
2025-10-01 00:08:37.363752 | 
2025-10-01 00:08:37.363817 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-01 00:08:37.395397 | controller | ok
2025-10-01 00:08:37.405995 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-01 00:08:37.414894 | 
2025-10-01 00:08:37.414957 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-01 00:08:37.439748 | controller | skipping: Conditional result was False
2025-10-01 00:08:37.447756 | 
2025-10-01 00:08:37.447827 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-01 00:08:38.099211 | controller | changed
2025-10-01 00:08:38.112338 | 
2025-10-01 00:08:38.112500 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-01 00:08:38.469731 | controller | ok
2025-10-01 00:08:38.485890 | 
2025-10-01 00:08:38.486072 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-01 00:08:39.812597 | controller | changed
2025-10-01 00:08:39.826214 | 
2025-10-01 00:08:39.826388 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-01 00:08:41.148013 | controller | changed
2025-10-01 00:08:41.161443 | 
2025-10-01 00:08:41.161588 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-01 00:08:41.199002 | controller | skipping: Conditional result was False
2025-10-01 00:08:41.207774 | 
2025-10-01 00:08:41.207869 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-01 00:08:41.787519 | controller -> localhost | changed
2025-10-01 00:08:41.799478 | 
2025-10-01 00:08:41.799563 | TASK [add-build-sshkey : Add back temp key]
2025-10-01 00:08:42.171463 | controller -> localhost | Identity added: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_rsa (zuul-build-sshkey)
2025-10-01 00:08:42.171796 | controller -> localhost | ok: Runtime: 0:00:00.017449
2025-10-01 00:08:42.180547 | 
2025-10-01 00:08:42.180636 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-01 00:08:42.741534 | controller | ok
2025-10-01 00:08:42.749446 | 
2025-10-01 00:08:42.749634 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-01 00:08:42.808744 | controller | skipping: Conditional result was False
2025-10-01 00:08:42.835804 | 
2025-10-01 00:08:42.835979 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-01 00:08:42.871618 | controller | ok
2025-10-01 00:08:42.905296 | 
2025-10-01 00:08:42.905486 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-01 00:08:43.161144 | controller -> localhost | ok
2025-10-01 00:08:43.178193 | 
2025-10-01 00:08:43.178396 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-01 00:08:43.222447 | controller | ok
2025-10-01 00:08:43.246600 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-01 00:08:43.254996 | 
2025-10-01 00:08:43.255170 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-01 00:08:43.627642 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-01 00:08:43.628223 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_ecdsa.
2025-10-01 00:08:43.628305 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_ecdsa.pub.
2025-10-01 00:08:43.628375 | controller -> localhost | The key fingerprint is:
2025-10-01 00:08:43.628418 | controller -> localhost | SHA256:HCrkG2n7Ka7vLfExxokNLfd8KN8nlP/7aqjDFgeZ5A0 zuul-build-sshkey
2025-10-01 00:08:43.628460 | controller -> localhost | The key's randomart image is:
2025-10-01 00:08:43.628499 | controller -> localhost | +---[ECDSA 521]---+
2025-10-01 00:08:43.628539 | controller -> localhost | |                 |
2025-10-01 00:08:43.628577 | controller -> localhost | |          E      |
2025-10-01 00:08:43.628615 | controller -> localhost | |    ..  .o =     |
2025-10-01 00:08:43.628652 | controller -> localhost | |   oo.oo .= .    |
2025-10-01 00:08:43.628781 | controller -> localhost | |    *B.+S. o     |
2025-10-01 00:08:43.628824 | controller -> localhost | |   .o=O + = .    |
2025-10-01 00:08:43.628860 | controller -> localhost | |    o+ = = + .   |
2025-10-01 00:08:43.628896 | controller -> localhost | |    oo... * + .  |
2025-10-01 00:08:43.628932 | controller -> localhost | |  .=+o+  ..= o++.|
2025-10-01 00:08:43.628967 | controller -> localhost | +----[SHA256]-----+
2025-10-01 00:08:43.629078 | controller -> localhost | ok: Runtime: 0:00:00.011029
2025-10-01 00:08:43.644105 | 
2025-10-01 00:08:43.644271 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-01 00:08:43.699607 | controller | ok
2025-10-01 00:08:43.713182 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-01 00:08:43.727705 | 
2025-10-01 00:08:43.727812 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-01 00:08:43.764845 | controller | skipping: Conditional result was False
2025-10-01 00:08:43.775941 | 
2025-10-01 00:08:43.776086 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-01 00:08:44.244601 | controller | changed
2025-10-01 00:08:44.259832 | 
2025-10-01 00:08:44.260045 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-01 00:08:44.640224 | controller | ok
2025-10-01 00:08:44.652282 | 
2025-10-01 00:08:44.652470 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-01 00:08:46.263225 | controller | changed
2025-10-01 00:08:46.272841 | 
2025-10-01 00:08:46.272937 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-01 00:08:47.578341 | controller | changed
2025-10-01 00:08:47.585935 | 
2025-10-01 00:08:47.586011 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-01 00:08:47.610722 | controller | skipping: Conditional result was False
2025-10-01 00:08:47.619351 | 
2025-10-01 00:08:47.619432 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-01 00:08:47.878914 | controller -> localhost | changed
2025-10-01 00:08:47.895251 | 
2025-10-01 00:08:47.895423 | TASK [add-build-sshkey : Add back temp key]
2025-10-01 00:08:48.269364 | controller -> localhost | Identity added: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/09852676c7ba4fa78daa052840bbede8_id_ecdsa (zuul-build-sshkey)
2025-10-01 00:08:48.269800 | controller -> localhost | ok: Runtime: 0:00:00.015194
2025-10-01 00:08:48.282443 | 
2025-10-01 00:08:48.282641 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-01 00:08:48.709475 | controller | ok
2025-10-01 00:08:48.722994 | 
2025-10-01 00:08:48.723192 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-01 00:08:48.761380 | controller | skipping: Conditional result was False
2025-10-01 00:08:48.775945 | 
2025-10-01 00:08:48.776086 | TASK [include_role : remove-zuul-sshkey]
2025-10-01 00:08:48.801207 | controller | skipping: Conditional result was False
2025-10-01 00:08:48.810501 | 
2025-10-01 00:08:48.810655 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-01 00:08:49.140323 | controller | ok: "logs"
2025-10-01 00:08:49.140705 | controller | ok: All items complete
2025-10-01 00:08:49.140751 | 
2025-10-01 00:08:49.435032 | controller | ok: "artifacts"
2025-10-01 00:08:49.722379 | controller | ok: "docs"
2025-10-01 00:08:49.743154 | 
2025-10-01 00:08:49.743317 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-01 00:08:50.075940 | controller | changed: "logs"
2025-10-01 00:08:50.360436 | controller | changed: "artifacts"
2025-10-01 00:08:50.657138 | controller | changed: "docs"
2025-10-01 00:08:50.713765 | 
2025-10-01 00:08:50.713968 | PLAY RECAP
2025-10-01 00:08:50.714037 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-01 00:08:50.714071 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-01 00:08:50.714100 | 
2025-10-01 00:08:50.896342 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-01 00:08:50.897822 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-01 00:08:51.571261 | 
2025-10-01 00:08:51.571434 | PLAY [all]
2025-10-01 00:08:51.597402 | 
2025-10-01 00:08:51.597584 | TASK [Install binary dependencies]
2025-10-01 00:08:51.660890 | controller | ok
2025-10-01 00:08:51.683836 | 
2025-10-01 00:08:51.684011 | TASK [bindep : Include find tasks]
2025-10-01 00:08:51.724790 | controller | ok
2025-10-01 00:08:51.734391 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-01 00:08:51.743117 | 
2025-10-01 00:08:51.743293 | TASK [bindep : Look for bindep.txt]
2025-10-01 00:08:52.332902 | controller | ok
2025-10-01 00:08:52.350287 | 
2025-10-01 00:08:52.350439 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:52.377148 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.389988 | 
2025-10-01 00:08:52.390109 | TASK [bindep : Look for other-requirements.txt]
2025-10-01 00:08:52.714924 | controller | ok
2025-10-01 00:08:52.730455 | 
2025-10-01 00:08:52.730767 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:52.768405 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.778159 | 
2025-10-01 00:08:52.778353 | TASK [bindep : Look for bindep fallback file]
2025-10-01 00:08:52.814393 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.825165 | 
2025-10-01 00:08:52.825354 | TASK [bindep : Define bindep_file fact]
2025-10-01 00:08:52.852351 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.861989 | 
2025-10-01 00:08:52.862110 | TASK [bindep : Include bindep tasks]
2025-10-01 00:08:52.898713 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.910573 | 
2025-10-01 00:08:52.910742 | TASK [bindep : Include install tasks]
2025-10-01 00:08:52.937440 | controller | skipping: Conditional result was False
2025-10-01 00:08:52.949962 | 
2025-10-01 00:08:52.950167 | LOOP [bindep : Include package tasks]
2025-10-01 00:08:53.012007 | 
2025-10-01 00:08:53.012260 | TASK [Run test-setup role]
2025-10-01 00:08:53.036439 | controller | ok
2025-10-01 00:08:53.064572 | 
2025-10-01 00:08:53.064778 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-01 00:08:53.401568 | controller | ok
2025-10-01 00:08:53.416981 | 
2025-10-01 00:08:53.417189 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-01 00:08:53.562575 | controller | skipping: Conditional result was False
2025-10-01 00:08:53.599214 | 
2025-10-01 00:08:53.599382 | PLAY RECAP
2025-10-01 00:08:53.599447 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-01 00:08:53.599476 | 
2025-10-01 00:08:53.774385 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-01 00:08:53.776620 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-01 00:08:54.391474 | 
2025-10-01 00:08:54.391646 | PLAY [controller]
2025-10-01 00:08:54.411891 | 
2025-10-01 00:08:54.411974 | TASK [Create the /root directory]
2025-10-01 00:08:55.175913 | controller | ok
2025-10-01 00:08:55.201068 | 
2025-10-01 00:08:55.201286 | TASK [Install glibc-langpack-en]
2025-10-01 00:09:03.205353 | controller | ok: Nothing to do
2025-10-01 00:09:03.211910 | 
2025-10-01 00:09:03.212002 | TASK [Ensure controller directory exists]
2025-10-01 00:09:03.690462 | controller | changed
2025-10-01 00:09:03.703392 | 
2025-10-01 00:09:03.703617 | TASK [Install container runtime]
2025-10-01 00:09:03.763475 | controller | ok
2025-10-01 00:09:03.813698 | 
2025-10-01 00:09:03.813883 | LOOP [ensure-podman : Find distribution installation]
2025-10-01 00:09:03.864505 | controller | ok: "/var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-01 00:09:03.883491 | controller | included: /var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-01 00:09:03.893514 | 
2025-10-01 00:09:03.893610 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-01 00:10:17.243331 | controller | changed
2025-10-01 00:10:17.256195 | 
2025-10-01 00:10:17.256353 | TASK [ensure-podman : Fetch podman version]
2025-10-01 00:10:18.005458 | controller | Client:       Podman Engine
2025-10-01 00:10:18.033804 | controller | Version:      4.6.2
2025-10-01 00:10:18.033855 | controller | API Version:  4.6.2
2025-10-01 00:10:18.034007 | controller | Go Version:   go1.19.12
2025-10-01 00:10:18.034046 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-01 00:10:18.034064 | controller | OS/Arch:      linux/amd64
2025-10-01 00:10:18.397417 | controller | ok: Runtime: 0:00:00.202409
2025-10-01 00:10:18.409499 | 
2025-10-01 00:10:18.409632 | TASK [ensure-podman : Print podman version installed]
2025-10-01 00:10:18.458166 | Podman version: Client:       Podman Engine
2025-10-01 00:10:18.458453 | Version:      4.6.2
2025-10-01 00:10:18.458519 | API Version:  4.6.2
2025-10-01 00:10:18.458567 | Go Version:   go1.19.12
2025-10-01 00:10:18.458609 | Built:        Mon Aug 28 19:38:31 2023
2025-10-01 00:10:18.458656 | OS/Arch:      linux/amd64
2025-10-01 00:10:18.471310 | 
2025-10-01 00:10:18.471446 | TASK [ensure-podman : Validate podman engine]
2025-10-01 00:10:18.635379 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.650946 | 
2025-10-01 00:10:18.651101 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-01 00:10:18.681994 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.697225 | 
2025-10-01 00:10:18.697313 | TASK [Ensure python3.8 is present]
2025-10-01 00:10:18.724690 | controller | skipping: Conditional result was False
2025-10-01 00:10:18.733944 | 
2025-10-01 00:10:18.734031 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-01 00:10:18.757341 | controller | ok
2025-10-01 00:10:18.783156 | 
2025-10-01 00:10:18.783243 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-01 00:10:22.467046 | controller | ok: Nothing to do
2025-10-01 00:10:22.478130 | 
2025-10-01 00:10:22.478253 | TASK [our-ensure-python : Also install python3-devel]
2025-10-01 00:10:35.307541 | controller | changed
2025-10-01 00:10:35.318319 | 
2025-10-01 00:10:35.318412 | TASK [Run ensure-virtualenv role]
2025-10-01 00:10:35.339262 | controller | ok
2025-10-01 00:10:35.360331 | 
2025-10-01 00:10:35.360435 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-01 00:10:35.711353 | controller | /usr/bin/virtualenv
2025-10-01 00:10:35.993407 | controller | ok: Runtime: 0:00:00.004358
2025-10-01 00:10:36.002493 | 
2025-10-01 00:10:36.002608 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-01 00:10:36.044792 | controller | skipping: Conditional result was False
2025-10-01 00:10:36.045249 | controller | ok: All items complete
2025-10-01 00:10:36.045302 | 
2025-10-01 00:10:36.060625 | 
2025-10-01 00:10:36.060809 | TASK [Find the full path of the Python interpreter]
2025-10-01 00:10:36.534877 | controller | /usr/bin/python3
2025-10-01 00:10:36.732462 | controller | ok
2025-10-01 00:10:36.739090 | 
2025-10-01 00:10:36.739194 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-01 00:10:38.102344 | controller | created virtual environment CPython3.11.0.final.0-64 in 737ms
2025-10-01 00:10:38.144852 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-01 00:10:38.144908 | 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-01 00:10:38.144926 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-01 00:10:38.144949 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-01 00:10:38.373328 | controller | changed
2025-10-01 00:10:38.383856 | 
2025-10-01 00:10:38.384061 | TASK [Set selinux package]
2025-10-01 00:10:38.418557 | controller | ok
2025-10-01 00:10:38.424250 | 
2025-10-01 00:10:38.424334 | TASK [Set selinux package (Fedora)]
2025-10-01 00:10:38.467062 | controller | ok
2025-10-01 00:10:38.472580 | 
2025-10-01 00:10:38.472650 | TASK [Install selinux into virtualenv]
2025-10-01 00:10:41.117816 | controller | Collecting selinux-please-lie-to-me
2025-10-01 00:10:41.211230 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-01 00:10:41.744349 | controller | Collecting setuptools<50.0.0
2025-10-01 00:10:41.758574 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-01 00:10:41.887347 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.5 MB/s eta 0:00:00
2025-10-01 00:10:42.039397 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-01 00:10:42.039695 | controller |   Attempting uninstall: setuptools
2025-10-01 00:10:42.044606 | controller |     Found existing installation: setuptools 62.6.0
2025-10-01 00:10:42.157164 | controller |     Uninstalling setuptools-62.6.0:
2025-10-01 00:10:42.172505 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-01 00:10:42.923899 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-01 00:10:43.138812 | controller |
2025-10-01 00:10:43.354692 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-01 00:10:43.354741 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-01 00:10:43.622916 | controller | ok: Runtime: 0:00:04.401158
2025-10-01 00:10:43.632797 | 
2025-10-01 00:10:43.632953 | TASK [Install pytest-forked into virtualenv]
2025-10-01 00:10:44.720878 | controller | Collecting pytest-forked
2025-10-01 00:10:44.807176 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-01 00:10:44.861741 | controller | Collecting py
2025-10-01 00:10:44.875449 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-01 00:10:44.910570 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-10-01 00:10:45.083659 | controller | Collecting pytest>=3.10
2025-10-01 00:10:45.097602 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-01 00:10:45.158034 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-01 00:10:45.211801 | controller | Collecting iniconfig>=1
2025-10-01 00:10:45.224118 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-01 00:10:45.289755 | controller | Collecting packaging>=20
2025-10-01 00:10:45.302696 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-01 00:10:45.314277 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.4 MB/s eta 0:00:00
2025-10-01 00:10:45.366805 | controller | Collecting pluggy<2,>=1.5
2025-10-01 00:10:45.378609 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-01 00:10:45.455200 | controller | Collecting pygments>=2.7.2
2025-10-01 00:10:45.466896 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-01 00:10:45.583357 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.8 MB/s eta 0:00:00
2025-10-01 00:10:45.712599 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-01 00:10:47.945185 | 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-01 00:10:47.960927 | controller |
2025-10-01 00:10:48.133457 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-01 00:10:48.133508 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-01 00:10:48.285842 | controller | ok: Runtime: 0:00:04.124389
2025-10-01 00:10:48.300941 | 
2025-10-01 00:10:48.301100 | TASK [Update pip]
2025-10-01 00:10:49.374880 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-01 00:10:49.643563 | controller | Collecting pip
2025-10-01 00:10:49.739850 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-01 00:10:49.943874 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.7 MB/s eta 0:00:00
2025-10-01 00:10:50.112968 | controller | Installing collected packages: pip
2025-10-01 00:10:50.114395 | controller |   Attempting uninstall: pip
2025-10-01 00:10:50.119145 | controller |     Found existing installation: pip 22.2.2
2025-10-01 00:10:50.438063 | controller |     Uninstalling pip-22.2.2:
2025-10-01 00:10:50.477181 | controller |       Successfully uninstalled pip-22.2.2
2025-10-01 00:10:52.240921 | controller | Successfully installed pip-25.2
2025-10-01 00:10:52.974193 | controller | ok: Runtime: 0:00:03.645637
2025-10-01 00:10:52.988821 | 
2025-10-01 00:10:52.988985 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-01 00:10:53.522369 | controller | changed
2025-10-01 00:10:53.534760 | 
2025-10-01 00:10:53.534895 | TASK [Install ansible into virtualenv]
2025-10-01 00:10:54.679995 | controller | Processing ./src/github.com/ansible/ansible
2025-10-01 00:10:54.686372 | controller |   Installing build dependencies: started
2025-10-01 00:10:56.631873 | controller |   Installing build dependencies: finished with status 'done'
2025-10-01 00:10:58.166161 | controller |   Getting requirements to build wheel: started
2025-10-01 00:10:58.166226 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-01 00:10:59.073169 | controller |   Preparing metadata (pyproject.toml): started
2025-10-01 00:10:59.073222 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-01 00:10:59.076547 | 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-01 00:10:59.081250 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-01 00:10:59.686579 | controller | ERROR
2025-10-01 00:10:59.686824 | controller | {
2025-10-01 00:10:59.686865 | controller |   "delta": "0:00:05.215796",
2025-10-01 00:10:59.686894 | controller |   "end": "2025-10-01 00:10:59.224672",
2025-10-01 00:10:59.686919 | controller |   "msg": "non-zero return code",
2025-10-01 00:10:59.686959 | controller |   "rc": 1,
2025-10-01 00:10:59.686985 | controller |   "start": "2025-10-01 00:10:54.008876"
2025-10-01 00:10:59.687008 | controller | }
failure
2025-10-01 00:10:59.689378 | 
2025-10-01 00:10:59.689431 | PLAY RECAP
2025-10-01 00:10:59.689487 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-01 00:10:59.689516 | 
2025-10-01 00:10:59.818238 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-01 00:10:59.820622 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-01 00:11:00.447620 | 
2025-10-01 00:11:00.447776 | PLAY [all]
2025-10-01 00:11:00.470129 | 
2025-10-01 00:11:00.470264 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-01 00:11:01.279627 | controller | changed: non-zero return code
2025-10-01 00:11:01.286366 | 
2025-10-01 00:11:01.286456 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-01 00:11:01.302156 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.308512 | 
2025-10-01 00:11:01.308611 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-01 00:11:01.329951 | 
2025-10-01 00:11:01.330134 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-01 00:11:01.351585 | 
2025-10-01 00:11:01.351795 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-01 00:11:01.365813 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.372726 | 
2025-10-01 00:11:01.372852 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-01 00:11:01.406453 | 
2025-10-01 00:11:01.406707 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-01 00:11:01.432455 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.442381 | 
2025-10-01 00:11:01.442487 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-01 00:11:01.468685 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.477296 | 
2025-10-01 00:11:01.477394 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-01 00:11:01.493360 | controller | skipping: Conditional result was False
2025-10-01 00:11:01.523405 | 
2025-10-01 00:11:01.523538 | PLAY RECAP
2025-10-01 00:11:01.523593 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-01 00:11:01.523618 | 
2025-10-01 00:11:01.660940 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-01 00:11:01.663578 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-01 00:11:02.329332 | 
2025-10-01 00:11:02.329464 | PLAY [all:!appliance*]
2025-10-01 00:11:02.351725 | 
2025-10-01 00:11:02.351877 | TASK [unregister the node]
2025-10-01 00:11:02.491126 | controller | skipping: Conditional result was False
2025-10-01 00:11:02.498166 | 
2025-10-01 00:11:02.498310 | TASK [include_role : fetch-output]
2025-10-01 00:11:02.529119 | controller | ok
2025-10-01 00:11:02.549065 | 
2025-10-01 00:11:02.549173 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-01 00:11:02.594449 | controller | skipping: Conditional result was False
2025-10-01 00:11:02.601019 | 
2025-10-01 00:11:02.601120 | TASK [fetch-output : Set log path for single node]
2025-10-01 00:11:02.630956 | controller | ok
2025-10-01 00:11:02.636881 | 
2025-10-01 00:11:02.636964 | LOOP [fetch-output : Ensure local output dirs]
2025-10-01 00:11:03.053834 | controller -> localhost | ok: "/var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/logs"
2025-10-01 00:11:03.302524 | controller -> localhost | changed: "/var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/artifacts"
2025-10-01 00:11:03.543377 | controller -> localhost | changed: "/var/lib/zuul/builds/09852676c7ba4fa78daa052840bbede8/work/docs"
2025-10-01 00:11:03.554587 | 
2025-10-01 00:11:03.554770 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-01 00:11:04.840478 | controller | changed:
2025-10-01 00:11:04.840767 | controller | .d..t...... ./
2025-10-01 00:11:04.840799 | controller | cd+++++++++ controller/
2025-10-01 00:11:04.840836 | controller | changed: All items complete
2025-10-01 00:11:04.840856 | 
2025-10-01 00:11:05.931459 | controller | changed: .d..t...... ./
2025-10-01 00:11:07.038755 | controller | changed: .d..t...... ./
2025-10-01 00:11:07.058781 | 
2025-10-01 00:11:07.058963 | TASK [include_role : fetch-output-openshift]
2025-10-01 00:11:07.084693 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.094984 | 
2025-10-01 00:11:07.095112 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-01 00:11:07.138645 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.151613 | controller | skipping: Conditional result was False
2025-10-01 00:11:07.188175 | 
2025-10-01 00:11:07.188341 | PLAY [localhost]
2025-10-01 00:11:07.201008 | 
2025-10-01 00:11:07.201110 | TASK [Run Zuul manifest role]
2025-10-01 00:11:07.220413 | localhost | ok
2025-10-01 00:11:07.234694 | 
2025-10-01 00:11:07.234849 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-01 00:11:07.624710 | localhost | changed
2025-10-01 00:11:07.629619 | 
2025-10-01 00:11:07.629717 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-01 00:11:07.669768 | localhost | ok
2025-10-01 00:11:07.679049 | 
2025-10-01 00:11:07.679150 | TASK [Set zuul-log-path fact]
2025-10-01 00:11:07.698467 | localhost | ok
2025-10-01 00:11:07.716294 | 
2025-10-01 00:11:07.716421 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-01 00:11:07.746928 | localhost | ok
2025-10-01 00:11:07.761301 | 
2025-10-01 00:11:07.761413 | LOOP [Run upload-logs-swift role]
2025-10-01 00:11:07.788548 | localhost | Output suppressed because no_log was given
2025-10-01 00:11:07.814702 | 
2025-10-01 00:11:07.814830 | TASK [Set zuul-log-path fact]
2025-10-01 00:11:07.839716 | localhost | skipping: Conditional result was False
2025-10-01 00:11:07.845186 | 
2025-10-01 00:11:07.845308 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-01 00:11:08.318426 | localhost -> localhost | ok: Runtime: 0:00:00.006395
2025-10-01 00:11:08.324132 | 
2025-10-01 00:11:08.324201 | TASK [upload-logs-swift : Upload logs to swift]