2026-01-09 00:13:11.927116 | Job console starting...
2026-01-09 00:13:11.942388 | Updating repositories
2026-01-09 00:13:12.093387 | Preparing job workspace
2026-01-09 00:13:15.866660 | Running Ansible setup...
2026-01-09 00:13:20.265583 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-09 00:13:20.944297 | 
2026-01-09 00:13:20.944431 | PLAY [localhost]
2026-01-09 00:13:20.952990 | 
2026-01-09 00:13:20.953060 | TASK [Gathering Facts]
2026-01-09 00:13:22.048265 | localhost | ok
2026-01-09 00:13:22.077307 | 
2026-01-09 00:13:22.077410 | TASK [Setup log path fact]
2026-01-09 00:13:22.098615 | localhost | ok
2026-01-09 00:13:22.115505 | 
2026-01-09 00:13:22.115599 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-09 00:13:22.171331 | localhost | ok
2026-01-09 00:13:22.189066 | 
2026-01-09 00:13:22.189166 | TASK [emit-job-header : Print job information]
2026-01-09 00:13:22.240230 | # Job Information
2026-01-09 00:13:22.240437 | Ansible Version: 2.15.12
2026-01-09 00:13:22.240481 | Job: ansible-test-sanity-docker-devel
2026-01-09 00:13:22.240509 | Pipeline: periodic
2026-01-09 00:13:22.240533 | Executor: ze02.softwarefactory-project.io
2026-01-09 00:13:22.240557 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-09 00:13:22.240585 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/55c/ansible/55c503101bb949f5b9cf34f53ad88a36/
2026-01-09 00:13:22.240611 | Event ID: 985433d38163455aa42d913504b2dc7d
2026-01-09 00:13:22.248866 | 
2026-01-09 00:13:22.248956 | LOOP [emit-job-header : Print node information]
2026-01-09 00:13:22.358944 | localhost | ok:
2026-01-09 00:13:22.359357 | localhost | # Node Information
2026-01-09 00:13:22.359467 | localhost | Inventory Hostname: controller
2026-01-09 00:13:22.359495 | localhost | Hostname: np0005578772
2026-01-09 00:13:22.359514 | localhost | Username: zuul
2026-01-09 00:13:22.359540 | localhost | Distro: Fedora 37
2026-01-09 00:13:22.359558 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2026-01-09 00:13:22.359575 | localhost | Region: ca-ymq-1
2026-01-09 00:13:22.359592 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-09 00:13:22.359607 | localhost | Product Name: OpenStack Nova
2026-01-09 00:13:22.359624 | localhost | Interface IP: 162.253.55.206
2026-01-09 00:13:22.377430 | 
2026-01-09 00:13:22.377519 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-09 00:13:22.855098 | localhost -> localhost | changed
2026-01-09 00:13:22.863173 | 
2026-01-09 00:13:22.863271 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-09 00:13:23.665854 | localhost -> localhost | changed
2026-01-09 00:13:23.685150 | 
2026-01-09 00:13:23.685210 | PLAY [all:!appliance*]
2026-01-09 00:13:23.700919 | 
2026-01-09 00:13:23.700985 | TASK [include_role : start-zuul-console]
2026-01-09 00:13:23.732693 | controller | ok
2026-01-09 00:13:23.747078 | 
2026-01-09 00:13:23.747143 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-09 00:13:24.141452 | controller | ok
2026-01-09 00:13:24.166843 | 
2026-01-09 00:13:24.167052 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-09 00:13:25.334638 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-09 00:13:25.340783 | 
2026-01-09 00:13:25.340846 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-09 00:13:25.871396 | controller | skipping: Conditional result was False
2026-01-09 00:13:25.888199 | 
2026-01-09 00:13:25.888409 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-09 00:13:25.906243 | controller | skipping: Conditional result was False
2026-01-09 00:13:25.920540 | 
2026-01-09 00:13:25.920723 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-09 00:13:25.938150 | controller | skipping: Conditional result was False
2026-01-09 00:13:25.952296 | 
2026-01-09 00:13:25.952462 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-09 00:13:25.970414 | controller | skipping: Conditional result was False
2026-01-09 00:13:25.984869 | 
2026-01-09 00:13:25.985164 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-09 00:13:26.012698 | controller | skipping: Conditional result was False
2026-01-09 00:13:26.022513 | 
2026-01-09 00:13:26.022609 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-09 00:13:26.048178 | controller | skipping: Conditional result was False
2026-01-09 00:13:26.072759 | 
2026-01-09 00:13:26.072851 | TASK [Disable Fedora Modular]
2026-01-09 00:13:26.344887 | controller | changed
2026-01-09 00:13:26.358103 | 
2026-01-09 00:13:26.358252 | TASK [Enable EPEL]
2026-01-09 00:13:26.396834 | controller | skipping: Conditional result was False
2026-01-09 00:13:26.410198 | 
2026-01-09 00:13:26.410344 | TASK [Register the RHEL node]
2026-01-09 00:13:26.977515 | 
2026-01-09 00:13:26.977823 | TASK [Show the subscription-manager status]
2026-01-09 00:13:27.572339 | controller | skipping: Conditional result was False
2026-01-09 00:13:27.579377 | 
2026-01-09 00:13:27.579441 | TASK [Enable EPEL on RHEL]
2026-01-09 00:13:28.144385 | controller | skipping: Conditional result was False
2026-01-09 00:13:28.157457 | 
2026-01-09 00:13:28.157614 | TASK [Install git and tox]
2026-01-09 00:14:53.006757 | controller | changed
2026-01-09 00:14:53.020783 | 
2026-01-09 00:14:53.020923 | TASK [include_role : prepare-workspace]
2026-01-09 00:14:53.060789 | controller | ok
2026-01-09 00:14:53.100826 | 
2026-01-09 00:14:53.100933 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-09 00:14:53.343037 | controller | ok
2026-01-09 00:14:53.358973 | 
2026-01-09 00:14:53.359158 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-09 00:15:05.314818 | controller | Output suppressed because no_log was given
2026-01-09 00:15:05.328439 | 
2026-01-09 00:15:05.328549 | TASK [include_role : prepare-workspace-openshift]
2026-01-09 00:15:05.354216 | controller | skipping: Conditional result was False
2026-01-09 00:15:05.424490 | 
2026-01-09 00:15:05.424586 | PLAY [all:!appliance]
2026-01-09 00:15:05.444368 | 
2026-01-09 00:15:05.444489 | TASK [Run add-build-sshkey role (RSA)]
2026-01-09 00:15:05.477821 | controller | ok
2026-01-09 00:15:05.499990 | 
2026-01-09 00:15:05.500086 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-09 00:15:05.821388 | controller -> localhost | ok
2026-01-09 00:15:05.834965 | 
2026-01-09 00:15:05.835098 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-09 00:15:05.864716 | controller | ok
2026-01-09 00:15:05.890642 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-09 00:15:05.900338 | 
2026-01-09 00:15:05.900431 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-09 00:15:06.537369 | controller -> localhost | Generating public/private rsa key pair.
2026-01-09 00:15:06.537595 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_rsa.
2026-01-09 00:15:06.537623 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_rsa.pub.
2026-01-09 00:15:06.537643 | controller -> localhost | The key fingerprint is:
2026-01-09 00:15:06.537686 | controller -> localhost | SHA256:kZ9chBilTyX0A8ndWEoEJK5M7M3DyXrvH24HYUZ/H50 zuul-build-sshkey
2026-01-09 00:15:06.537712 | controller -> localhost | The key's randomart image is:
2026-01-09 00:15:06.537731 | controller -> localhost | +---[RSA 2048]----+
2026-01-09 00:15:06.537749 | controller -> localhost | |        oBB*=+.  |
2026-01-09 00:15:06.537767 | controller -> localhost | |     . ..++B+..  |
2026-01-09 00:15:06.537785 | controller -> localhost | |      o = ..=.  o|
2026-01-09 00:15:06.537801 | controller -> localhost | |     + * B o+..Eo|
2026-01-09 00:15:06.537818 | controller -> localhost | |      + S =o . .o|
2026-01-09 00:15:06.537842 | controller -> localhost | |       . .  .   .|
2026-01-09 00:15:06.537863 | controller -> localhost | |      . .   ..   |
2026-01-09 00:15:06.537881 | controller -> localhost | |       . . ....  |
2026-01-09 00:15:06.537898 | controller -> localhost | |         .ooo.   |
2026-01-09 00:15:06.537917 | controller -> localhost | +----[SHA256]-----+
2026-01-09 00:15:06.537971 | controller -> localhost | ok: Runtime: 0:00:00.120797
2026-01-09 00:15:06.544688 | 
2026-01-09 00:15:06.544749 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-09 00:15:06.575591 | controller | ok
2026-01-09 00:15:06.585458 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-09 00:15:06.594181 | 
2026-01-09 00:15:06.594242 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-09 00:15:06.618297 | controller | skipping: Conditional result was False
2026-01-09 00:15:06.625829 | 
2026-01-09 00:15:06.625898 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-09 00:15:07.068631 | controller | changed
2026-01-09 00:15:07.083456 | 
2026-01-09 00:15:07.083727 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-09 00:15:07.325784 | controller | ok
2026-01-09 00:15:07.336066 | 
2026-01-09 00:15:07.336182 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-09 00:15:08.018542 | controller | changed
2026-01-09 00:15:08.026646 | 
2026-01-09 00:15:08.026751 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-09 00:15:08.619739 | controller | changed
2026-01-09 00:15:08.625481 | 
2026-01-09 00:15:08.625542 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-09 00:15:08.660711 | controller | skipping: Conditional result was False
2026-01-09 00:15:08.667186 | 
2026-01-09 00:15:08.667245 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-09 00:15:09.108311 | controller -> localhost | changed
2026-01-09 00:15:09.119686 | 
2026-01-09 00:15:09.119753 | TASK [add-build-sshkey : Add back temp key]
2026-01-09 00:15:09.448330 | controller -> localhost | Identity added: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_rsa (zuul-build-sshkey)
2026-01-09 00:15:09.448596 | controller -> localhost | ok: Runtime: 0:00:00.008649
2026-01-09 00:15:09.454938 | 
2026-01-09 00:15:09.455000 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-09 00:15:09.831308 | controller | ok
2026-01-09 00:15:09.844002 | 
2026-01-09 00:15:09.844296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-09 00:15:09.881787 | controller | skipping: Conditional result was False
2026-01-09 00:15:09.908589 | 
2026-01-09 00:15:09.908861 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-09 00:15:09.948508 | controller | ok
2026-01-09 00:15:09.973520 | 
2026-01-09 00:15:09.973609 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-09 00:15:10.257421 | controller -> localhost | ok
2026-01-09 00:15:10.263884 | 
2026-01-09 00:15:10.263947 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-09 00:15:10.294131 | controller | ok
2026-01-09 00:15:10.304784 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-09 00:15:10.310630 | 
2026-01-09 00:15:10.310705 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-09 00:15:10.629353 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-09 00:15:10.629594 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_ecdsa.
2026-01-09 00:15:10.629622 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_ecdsa.pub.
2026-01-09 00:15:10.629652 | controller -> localhost | The key fingerprint is:
2026-01-09 00:15:10.629691 | controller -> localhost | SHA256:qdyhl6agWKhU9sQigsQ/iOMekJsu5kSu4uwVRxtFRRw zuul-build-sshkey
2026-01-09 00:15:10.629712 | controller -> localhost | The key's randomart image is:
2026-01-09 00:15:10.629730 | controller -> localhost | +---[ECDSA 521]---+
2026-01-09 00:15:10.629747 | controller -> localhost | |      .o+E.      |
2026-01-09 00:15:10.629764 | controller -> localhost | |.     .  .       |
2026-01-09 00:15:10.629781 | controller -> localhost | | o   o           |
2026-01-09 00:15:10.629798 | controller -> localhost | |+.o o o  .       |
2026-01-09 00:15:10.629814 | controller -> localhost | |B+ B =  S        |
2026-01-09 00:15:10.629831 | controller -> localhost | |*=+ B. + o       |
2026-01-09 00:15:10.629847 | controller -> localhost | |+*....+ =        |
2026-01-09 00:15:10.629864 | controller -> localhost | |@+o. . +         |
2026-01-09 00:15:10.629880 | controller -> localhost | |@B.   .          |
2026-01-09 00:15:10.629897 | controller -> localhost | +----[SHA256]-----+
2026-01-09 00:15:10.629946 | controller -> localhost | ok: Runtime: 0:00:00.015423
2026-01-09 00:15:10.637513 | 
2026-01-09 00:15:10.637575 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-09 00:15:10.667745 | controller | ok
2026-01-09 00:15:10.674966 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-09 00:15:10.683769 | 
2026-01-09 00:15:10.683833 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-09 00:15:10.718385 | controller | skipping: Conditional result was False
2026-01-09 00:15:10.726554 | 
2026-01-09 00:15:10.726646 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-09 00:15:11.007918 | controller | changed
2026-01-09 00:15:11.022530 | 
2026-01-09 00:15:11.022718 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-09 00:15:11.265287 | controller | ok
2026-01-09 00:15:11.275551 | 
2026-01-09 00:15:11.275687 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-09 00:15:11.935364 | controller | changed
2026-01-09 00:15:11.948176 | 
2026-01-09 00:15:11.948323 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-09 00:15:12.612030 | controller | changed
2026-01-09 00:15:12.627017 | 
2026-01-09 00:15:12.627211 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-09 00:15:12.654725 | controller | skipping: Conditional result was False
2026-01-09 00:15:12.669431 | 
2026-01-09 00:15:12.669607 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-09 00:15:12.983305 | controller -> localhost | changed
2026-01-09 00:15:13.009437 | 
2026-01-09 00:15:13.009624 | TASK [add-build-sshkey : Add back temp key]
2026-01-09 00:15:13.415693 | controller -> localhost | Identity added: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/55c503101bb949f5b9cf34f53ad88a36_id_ecdsa (zuul-build-sshkey)
2026-01-09 00:15:13.415992 | controller -> localhost | ok: Runtime: 0:00:00.007149
2026-01-09 00:15:13.422463 | 
2026-01-09 00:15:13.422525 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-09 00:20:16.743602 | controller | ok
2026-01-09 00:20:16.756116 | 
2026-01-09 00:20:16.756252 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-09 00:20:16.794571 | controller | skipping: Conditional result was False
2026-01-09 00:20:16.820916 | 
2026-01-09 00:20:16.821058 | TASK [include_role : remove-zuul-sshkey]
2026-01-09 00:20:16.850194 | controller | skipping: Conditional result was False
2026-01-09 00:20:16.866950 | 
2026-01-09 00:20:16.867098 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-09 00:20:17.139170 | controller | ok: "logs"
2026-01-09 00:20:17.139770 | controller | ok: All items complete
2026-01-09 00:20:17.139843 | 
2026-01-09 00:20:17.346013 | controller | ok: "artifacts"
2026-01-09 00:20:17.558653 | controller | ok: "docs"
2026-01-09 00:20:17.586231 | 
2026-01-09 00:20:17.586483 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-09 00:20:17.849966 | controller | changed: "logs"
2026-01-09 00:20:18.048360 | controller | changed: "artifacts"
2026-01-09 00:20:18.240435 | controller | changed: "docs"
2026-01-09 00:20:18.300724 | 
2026-01-09 00:20:18.300882 | PLAY RECAP
2026-01-09 00:20:18.300944 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-09 00:20:18.300980 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-09 00:20:18.301003 | 
2026-01-09 00:20:18.442705 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-09 00:20:18.443621 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-09 00:20:19.012511 | 
2026-01-09 00:20:19.012622 | PLAY [all]
2026-01-09 00:20:19.033802 | 
2026-01-09 00:20:19.033880 | TASK [Install binary dependencies]
2026-01-09 00:20:19.105896 | controller | ok
2026-01-09 00:20:19.132470 | 
2026-01-09 00:20:19.132576 | TASK [bindep : Include find tasks]
2026-01-09 00:20:19.175353 | controller | ok
2026-01-09 00:20:19.186055 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-09 00:20:19.194631 | 
2026-01-09 00:20:19.194736 | TASK [bindep : Look for bindep.txt]
2026-01-09 00:20:19.775042 | controller | ok
2026-01-09 00:20:19.789890 | 
2026-01-09 00:20:19.790080 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:20:19.822076 | controller | skipping: Conditional result was False
2026-01-09 00:20:19.835316 | 
2026-01-09 00:20:19.835590 | TASK [bindep : Look for other-requirements.txt]
2026-01-09 00:20:20.068088 | controller | ok
2026-01-09 00:20:20.080932 | 
2026-01-09 00:20:20.081083 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:20:20.118367 | controller | skipping: Conditional result was False
2026-01-09 00:20:20.131732 | 
2026-01-09 00:20:20.131877 | TASK [bindep : Look for bindep fallback file]
2026-01-09 00:20:20.179477 | controller | skipping: Conditional result was False
2026-01-09 00:20:20.194172 | 
2026-01-09 00:20:20.194316 | TASK [bindep : Define bindep_file fact]
2026-01-09 00:20:20.231409 | controller | skipping: Conditional result was False
2026-01-09 00:20:20.244347 | 
2026-01-09 00:20:20.244483 | TASK [bindep : Include bindep tasks]
2026-01-09 00:20:20.281646 | controller | skipping: Conditional result was False
2026-01-09 00:20:20.296027 | 
2026-01-09 00:20:20.296168 | TASK [bindep : Include install tasks]
2026-01-09 00:20:20.333374 | controller | skipping: Conditional result was False
2026-01-09 00:20:20.347494 | 
2026-01-09 00:20:20.347632 | LOOP [bindep : Include package tasks]
2026-01-09 00:20:20.428883 | 
2026-01-09 00:20:20.429138 | TASK [Run test-setup role]
2026-01-09 00:20:20.461433 | controller | ok
2026-01-09 00:20:20.489651 | 
2026-01-09 00:20:20.489756 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-09 00:20:20.730305 | controller | ok
2026-01-09 00:20:20.743714 | 
2026-01-09 00:20:20.743851 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-09 00:20:21.296797 | controller | skipping: Conditional result was False
2026-01-09 00:20:21.351968 | 
2026-01-09 00:20:21.352176 | PLAY RECAP
2026-01-09 00:20:21.352245 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-09 00:20:21.352273 | 
2026-01-09 00:20:21.481913 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-09 00:20:21.482817 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-09 00:20:22.054974 | 
2026-01-09 00:20:22.055105 | PLAY [controller]
2026-01-09 00:20:22.075347 | 
2026-01-09 00:20:22.075431 | TASK [Create the /root directory]
2026-01-09 00:20:22.645369 | controller | ok
2026-01-09 00:20:22.658774 | 
2026-01-09 00:20:22.658938 | TASK [Install glibc-langpack-en]
2026-01-09 00:20:26.550139 | controller | ok: Nothing to do
2026-01-09 00:20:26.558128 | 
2026-01-09 00:20:26.558212 | TASK [Ensure controller directory exists]
2026-01-09 00:20:26.769974 | controller | changed
2026-01-09 00:20:26.785141 | 
2026-01-09 00:20:26.785288 | TASK [Install container runtime]
2026-01-09 00:20:26.848856 | controller | ok
2026-01-09 00:20:26.909838 | 
2026-01-09 00:20:26.909963 | LOOP [ensure-podman : Find distribution installation]
2026-01-09 00:20:26.940361 | controller | ok: "/var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-09 00:20:26.957929 | controller | included: /var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-09 00:20:26.973866 | 
2026-01-09 00:20:26.974176 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-09 00:21:33.281980 | controller | changed
2026-01-09 00:21:33.299525 | 
2026-01-09 00:21:33.299714 | TASK [ensure-podman : Fetch podman version]
2026-01-09 00:21:33.837334 | controller | Client:       Podman Engine
2026-01-09 00:21:33.861897 | controller | Version:      4.6.2
2026-01-09 00:21:33.862001 | controller | API Version:  4.6.2
2026-01-09 00:21:33.862016 | controller | Go Version:   go1.19.12
2026-01-09 00:21:33.862040 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-09 00:21:33.862053 | controller | OS/Arch:      linux/amd64
2026-01-09 00:21:34.347149 | controller | ok: Runtime: 0:00:00.177279
2026-01-09 00:21:34.356636 | 
2026-01-09 00:21:34.356784 | TASK [ensure-podman : Print podman version installed]
2026-01-09 00:21:34.391408 | Podman version: Client:       Podman Engine
2026-01-09 00:21:34.391603 | Version:      4.6.2
2026-01-09 00:21:34.391642 | API Version:  4.6.2
2026-01-09 00:21:34.391694 | Go Version:   go1.19.12
2026-01-09 00:21:34.391723 | Built:        Mon Aug 28 19:38:31 2023
2026-01-09 00:21:34.391752 | OS/Arch:      linux/amd64
2026-01-09 00:21:34.401192 | 
2026-01-09 00:21:34.401363 | TASK [ensure-podman : Validate podman engine]
2026-01-09 00:21:34.947451 | controller | skipping: Conditional result was False
2026-01-09 00:21:34.956876 | 
2026-01-09 00:21:34.956980 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-09 00:21:34.982932 | controller | skipping: Conditional result was False
2026-01-09 00:21:34.999091 | 
2026-01-09 00:21:34.999201 | TASK [Ensure python3.8 is present]
2026-01-09 00:21:35.014981 | controller | skipping: Conditional result was False
2026-01-09 00:21:35.024833 | 
2026-01-09 00:21:35.024930 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-09 00:21:35.048710 | controller | ok
2026-01-09 00:21:35.076787 | 
2026-01-09 00:21:35.076924 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-09 00:21:36.615200 | controller | ok: Nothing to do
2026-01-09 00:21:36.628520 | 
2026-01-09 00:21:36.628764 | TASK [our-ensure-python : Also install python3-devel]
2026-01-09 00:21:45.841305 | controller | changed
2026-01-09 00:21:45.864289 | 
2026-01-09 00:21:45.864422 | TASK [Run ensure-virtualenv role]
2026-01-09 00:21:45.895405 | controller | ok
2026-01-09 00:21:45.927897 | 
2026-01-09 00:21:45.927983 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-09 00:21:46.214477 | controller | /usr/bin/virtualenv
2026-01-09 00:21:46.490779 | controller | ok: Runtime: 0:00:00.004508
2026-01-09 00:21:46.502879 | 
2026-01-09 00:21:46.503011 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-09 00:21:46.540084 | controller | skipping: Conditional result was False
2026-01-09 00:21:46.540619 | controller | ok: All items complete
2026-01-09 00:21:46.540744 | 
2026-01-09 00:21:46.565790 | 
2026-01-09 00:21:46.565972 | TASK [Find the full path of the Python interpreter]
2026-01-09 00:21:46.826910 | controller | /usr/bin/python3
2026-01-09 00:21:47.113848 | controller | ok
2026-01-09 00:21:47.125567 | 
2026-01-09 00:21:47.125740 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-09 00:21:48.051393 | controller | created virtual environment CPython3.11.0.final.0-64 in 599ms
2026-01-09 00:21:48.083981 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-09 00:21:48.084832 | 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/.local/share/virtualenv)
2026-01-09 00:21:48.084913 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-09 00:21:48.084947 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-09 00:21:48.186431 | controller | changed
2026-01-09 00:21:48.200795 | 
2026-01-09 00:21:48.200951 | TASK [Set selinux package]
2026-01-09 00:21:48.242402 | controller | ok
2026-01-09 00:21:48.254035 | 
2026-01-09 00:21:48.254170 | TASK [Set selinux package (Fedora)]
2026-01-09 00:21:48.304774 | controller | ok
2026-01-09 00:21:48.317916 | 
2026-01-09 00:21:48.318055 | TASK [Install selinux into virtualenv]
2026-01-09 00:21:49.605307 | controller | Collecting selinux-please-lie-to-me
2026-01-09 00:21:49.647564 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-09 00:21:49.941921 | controller | Collecting setuptools<50.0.0
2026-01-09 00:21:49.947274 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-09 00:21:49.996235 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.9 MB/s eta 0:00:00
2026-01-09 00:21:50.078973 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-09 00:21:50.079187 | controller |   Attempting uninstall: setuptools
2026-01-09 00:21:50.081603 | controller |     Found existing installation: setuptools 62.6.0
2026-01-09 00:21:50.141055 | controller |     Uninstalling setuptools-62.6.0:
2026-01-09 00:21:50.148962 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-09 00:21:50.509684 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-09 00:21:50.632793 | controller |
2026-01-09 00:21:50.715245 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-09 00:21:50.715293 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-09 00:21:50.880899 | controller | ok: Runtime: 0:00:02.152058
2026-01-09 00:21:50.892912 | 
2026-01-09 00:21:50.893038 | TASK [Install pytest-forked into virtualenv]
2026-01-09 00:21:51.493305 | controller | Collecting pytest-forked
2026-01-09 00:21:51.528616 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-09 00:21:51.572994 | controller | Collecting py
2026-01-09 00:21:51.576068 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-09 00:21:51.595737 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.4 MB/s eta 0:00:00
2026-01-09 00:21:51.699961 | controller | Collecting pytest>=3.10
2026-01-09 00:21:51.705006 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-09 00:21:51.720664 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 29.2 MB/s eta 0:00:00
2026-01-09 00:21:51.754176 | controller | Collecting iniconfig>=1.0.1
2026-01-09 00:21:51.758049 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-09 00:21:51.796408 | controller | Collecting packaging>=22
2026-01-09 00:21:51.800066 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2026-01-09 00:21:51.807393 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.4 MB/s eta 0:00:00
2026-01-09 00:21:51.839149 | controller | Collecting pluggy<2,>=1.5
2026-01-09 00:21:51.842291 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-09 00:21:51.895236 | controller | Collecting pygments>=2.7.2
2026-01-09 00:21:51.898527 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-09 00:21:51.924208 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 53.1 MB/s eta 0:00:00
2026-01-09 00:21:52.012369 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-09 00:21:53.141844 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2026-01-09 00:21:53.150598 | controller |
2026-01-09 00:21:53.219143 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-09 00:21:53.219157 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-09 00:21:53.453653 | controller | ok: Runtime: 0:00:02.093011
2026-01-09 00:21:53.461871 | 
2026-01-09 00:21:53.461959 | TASK [Update pip]
2026-01-09 00:21:54.013039 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-09 00:22:30.316222 | controller | Collecting pip
2026-01-09 00:22:42.637661 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-09 00:22:42.698937 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.9 MB/s eta 0:00:00
2026-01-09 00:22:42.764173 | controller | Installing collected packages: pip
2026-01-09 00:22:42.764397 | controller |   Attempting uninstall: pip
2026-01-09 00:22:42.766814 | controller |     Found existing installation: pip 22.2.2
2026-01-09 00:22:42.908766 | controller |     Uninstalling pip-22.2.2:
2026-01-09 00:22:42.923912 | controller |       Successfully uninstalled pip-22.2.2
2026-01-09 00:22:43.749573 | controller | Successfully installed pip-25.3
2026-01-09 00:22:44.040754 | controller | ok: Runtime: 0:00:50.136679
2026-01-09 00:22:44.053285 | 
2026-01-09 00:22:44.053412 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-09 00:22:44.276329 | controller | changed
2026-01-09 00:22:44.289079 | 
2026-01-09 00:22:44.289212 | TASK [Install ansible into virtualenv]
2026-01-09 00:22:44.806681 | controller | Processing ./src/github.com/ansible/ansible
2026-01-09 00:22:44.810152 | controller |   Installing build dependencies: started
2026-01-09 00:23:07.615100 | controller |   Installing build dependencies: finished with status 'done'
2026-01-09 00:23:07.617241 | controller |   Getting requirements to build wheel: started
2026-01-09 00:23:08.460490 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-09 00:23:08.462364 | controller |   Preparing metadata (pyproject.toml): started
2026-01-09 00:23:08.967969 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-09 00:23:08.973708 | 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.
2026-01-09 00:23:08.978062 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-09 00:23:09.353985 | controller | ERROR
2026-01-09 00:23:09.354322 | controller | {
2026-01-09 00:23:09.354384 | controller |   "delta": "0:00:24.549782",
2026-01-09 00:23:09.354425 | controller |   "end": "2026-01-09 00:23:09.075765",
2026-01-09 00:23:09.354463 | controller |   "msg": "non-zero return code",
2026-01-09 00:23:09.354517 | controller |   "rc": 1,
2026-01-09 00:23:09.354555 | controller |   "start": "2026-01-09 00:22:44.525983"
2026-01-09 00:23:09.354589 | controller | }
failure
2026-01-09 00:23:09.358029 | 
2026-01-09 00:23:09.358130 | PLAY RECAP
2026-01-09 00:23:09.358211 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-09 00:23:09.358253 | 
2026-01-09 00:23:09.485112 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-09 00:23:09.486226 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-09 00:23:10.097133 | 
2026-01-09 00:23:10.097263 | PLAY [all]
2026-01-09 00:23:10.119444 | 
2026-01-09 00:23:10.119533 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-09 00:23:10.516222 | controller | changed: non-zero return code
2026-01-09 00:23:10.529336 | 
2026-01-09 00:23:10.529493 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-09 00:23:10.557425 | controller | skipping: Conditional result was False
2026-01-09 00:23:10.571932 | 
2026-01-09 00:23:10.572083 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-09 00:23:10.612058 | 
2026-01-09 00:23:10.612231 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-09 00:23:10.645780 | 
2026-01-09 00:23:10.645950 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-09 00:23:10.670592 | controller | skipping: Conditional result was False
2026-01-09 00:23:10.680761 | 
2026-01-09 00:23:10.680849 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-09 00:23:10.718524 | 
2026-01-09 00:23:10.718821 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-09 00:23:10.735159 | controller | skipping: Conditional result was False
2026-01-09 00:23:10.744107 | 
2026-01-09 00:23:10.744199 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-09 00:23:10.769470 | controller | skipping: Conditional result was False
2026-01-09 00:23:10.783644 | 
2026-01-09 00:23:10.783823 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-09 00:23:10.809275 | controller | skipping: Conditional result was False
2026-01-09 00:23:10.846169 | 
2026-01-09 00:23:10.846251 | PLAY RECAP
2026-01-09 00:23:10.846309 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-09 00:23:10.846336 | 
2026-01-09 00:23:10.960003 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-09 00:23:10.961123 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-09 00:23:11.546398 | 
2026-01-09 00:23:11.546515 | PLAY [all:!appliance*]
2026-01-09 00:23:11.567906 | 
2026-01-09 00:23:11.567981 | TASK [unregister the node]
2026-01-09 00:23:12.099136 | controller | skipping: Conditional result was False
2026-01-09 00:23:12.112277 | 
2026-01-09 00:23:12.112438 | TASK [include_role : fetch-output]
2026-01-09 00:23:12.163002 | controller | ok
2026-01-09 00:23:12.200784 | 
2026-01-09 00:23:12.200879 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-09 00:23:12.276876 | controller | skipping: Conditional result was False
2026-01-09 00:23:12.285068 | 
2026-01-09 00:23:12.285159 | TASK [fetch-output : Set log path for single node]
2026-01-09 00:23:12.328222 | controller | ok
2026-01-09 00:23:12.335728 | 
2026-01-09 00:23:12.335814 | LOOP [fetch-output : Ensure local output dirs]
2026-01-09 00:23:12.756440 | controller -> localhost | ok: "/var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/logs"
2026-01-09 00:23:13.000492 | controller -> localhost | changed: "/var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/artifacts"
2026-01-09 00:23:13.263207 | controller -> localhost | changed: "/var/lib/zuul/builds/55c503101bb949f5b9cf34f53ad88a36/work/docs"
2026-01-09 00:23:13.281511 | 
2026-01-09 00:23:13.281644 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-09 00:23:13.967492 | controller | changed:
2026-01-09 00:23:13.967887 | controller | .d..t...... ./
2026-01-09 00:23:13.967952 | controller | cd+++++++++ controller/
2026-01-09 00:23:13.968023 | controller | changed: All items complete
2026-01-09 00:23:13.968069 | 
2026-01-09 00:23:14.559803 | controller | changed: .d..t...... ./
2026-01-09 00:23:15.082327 | controller | changed: .d..t...... ./
2026-01-09 00:23:15.100051 | 
2026-01-09 00:23:15.100208 | TASK [include_role : fetch-output-openshift]
2026-01-09 00:23:15.125378 | controller | skipping: Conditional result was False
2026-01-09 00:23:15.134252 | 
2026-01-09 00:23:15.134356 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-09 00:23:15.187167 | controller | skipping: Conditional result was False
2026-01-09 00:23:15.198724 | controller | skipping: Conditional result was False
2026-01-09 00:23:15.239057 | 
2026-01-09 00:23:15.239171 | PLAY [localhost]
2026-01-09 00:23:15.255632 | 
2026-01-09 00:23:15.255734 | TASK [Run Zuul manifest role]
2026-01-09 00:23:15.276249 | localhost | ok
2026-01-09 00:23:15.294838 | 
2026-01-09 00:23:15.294924 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-09 00:23:15.708574 | localhost | changed
2026-01-09 00:23:15.713288 | 
2026-01-09 00:23:15.713346 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-09 00:23:15.752155 | localhost | ok
2026-01-09 00:23:15.759890 | 
2026-01-09 00:23:15.759947 | TASK [Set zuul-log-path fact]
2026-01-09 00:23:15.779068 | localhost | ok
2026-01-09 00:23:15.792571 | 
2026-01-09 00:23:15.792635 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-09 00:23:15.830922 | localhost | ok
2026-01-09 00:23:15.838650 | 
2026-01-09 00:23:15.838742 | LOOP [Run upload-logs-swift role]
2026-01-09 00:23:15.884446 | localhost | Output suppressed because no_log was given
2026-01-09 00:23:15.907981 | 
2026-01-09 00:23:15.908042 | TASK [Set zuul-log-path fact]
2026-01-09 00:23:15.942279 | localhost | skipping: Conditional result was False
2026-01-09 00:23:15.949097 | 
2026-01-09 00:23:15.949184 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-09 00:23:16.445742 | localhost -> localhost | ok: Runtime: 0:00:00.005586
2026-01-09 00:23:16.493218 | 
2026-01-09 00:23:16.493368 | TASK [upload-logs-swift : Upload logs to swift]