2025-11-07 00:06:37.307848 | Job console starting...
2025-11-07 00:06:37.316721 | Updating repositories
2025-11-07 00:06:37.426089 | Preparing job workspace
2025-11-07 00:06:41.946029 | Running Ansible setup...
2025-11-07 00:06:47.858939 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-07 00:06:48.485647 | 
2025-11-07 00:06:48.485839 | PLAY [localhost]
2025-11-07 00:06:48.494861 | 
2025-11-07 00:06:48.494967 | TASK [Gathering Facts]
2025-11-07 00:06:49.498900 | localhost | ok
2025-11-07 00:06:49.532083 | 
2025-11-07 00:06:49.532294 | TASK [Setup log path fact]
2025-11-07 00:06:49.554320 | localhost | ok
2025-11-07 00:06:49.572073 | 
2025-11-07 00:06:49.572170 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-07 00:06:49.614761 | localhost | ok
2025-11-07 00:06:49.630796 | 
2025-11-07 00:06:49.630919 | TASK [emit-job-header : Print job information]
2025-11-07 00:06:49.692440 | # Job Information
2025-11-07 00:06:49.692654 | Ansible Version: 2.15.12
2025-11-07 00:06:49.692729 | Job: ansible-test-sanity-docker-devel
2025-11-07 00:06:49.692762 | Pipeline: periodic
2025-11-07 00:06:49.692790 | Executor: ze04.softwarefactory-project.io
2025-11-07 00:06:49.692817 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-07 00:06:49.692848 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/e0d/ansible/e0db87d48605402f94944efd1edda587/
2025-11-07 00:06:49.692901 | Event ID: 75db9354acf84300bc89d0c9903cd922
2025-11-07 00:06:49.698641 | 
2025-11-07 00:06:49.698758 | LOOP [emit-job-header : Print node information]
2025-11-07 00:06:49.821411 | localhost | ok:
2025-11-07 00:06:49.821624 | localhost | # Node Information
2025-11-07 00:06:49.821653 | localhost | Inventory Hostname: controller
2025-11-07 00:06:49.821694 | localhost | Hostname: np0005514184
2025-11-07 00:06:49.821721 | localhost | Username: zuul
2025-11-07 00:06:49.821748 | localhost | Distro: Fedora 37
2025-11-07 00:06:49.821768 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-07 00:06:49.821787 | localhost | Region: ca-ymq-1
2025-11-07 00:06:49.821805 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-07 00:06:49.821823 | localhost | Product Name: OpenStack Nova
2025-11-07 00:06:49.821840 | localhost | Interface IP: 162.253.55.145
2025-11-07 00:06:49.845519 | 
2025-11-07 00:06:49.845759 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-07 00:06:50.302088 | localhost -> localhost | changed
2025-11-07 00:06:50.307742 | 
2025-11-07 00:06:50.307810 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-07 00:06:51.586504 | localhost -> localhost | changed
2025-11-07 00:06:51.615065 | 
2025-11-07 00:06:51.615172 | PLAY [all:!appliance*]
2025-11-07 00:06:51.638874 | 
2025-11-07 00:06:51.638974 | TASK [include_role : start-zuul-console]
2025-11-07 00:06:51.659381 | controller | ok
2025-11-07 00:06:51.672721 | 
2025-11-07 00:06:51.672810 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-07 00:06:52.054393 | controller | ok
2025-11-07 00:06:52.080929 | 
2025-11-07 00:06:52.081118 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-07 00:07:41.545746 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-07 00:07:41.669075 | 
2025-11-07 00:07:41.669240 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-07 00:07:42.216809 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.230525 | 
2025-11-07 00:07:42.230738 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-07 00:07:42.247640 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.261451 | 
2025-11-07 00:07:42.261615 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-07 00:07:42.288580 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.298706 | 
2025-11-07 00:07:42.298890 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-07 00:07:42.326069 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.337369 | 
2025-11-07 00:07:42.337513 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-07 00:07:42.362262 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.371098 | 
2025-11-07 00:07:42.371217 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-07 00:07:42.395184 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.408502 | 
2025-11-07 00:07:42.408615 | TASK [Disable Fedora Modular]
2025-11-07 00:07:42.641804 | controller | changed
2025-11-07 00:07:42.651073 | 
2025-11-07 00:07:42.651206 | TASK [Enable EPEL]
2025-11-07 00:07:42.676350 | controller | skipping: Conditional result was False
2025-11-07 00:07:42.684745 | 
2025-11-07 00:07:42.684859 | TASK [Register the RHEL node]
2025-11-07 00:07:43.241974 | 
2025-11-07 00:07:43.242139 | TASK [Show the subscription-manager status]
2025-11-07 00:07:43.787556 | controller | skipping: Conditional result was False
2025-11-07 00:07:43.802358 | 
2025-11-07 00:07:43.802447 | TASK [Enable EPEL on RHEL]
2025-11-07 00:07:44.351078 | controller | skipping: Conditional result was False
2025-11-07 00:07:44.358597 | 
2025-11-07 00:07:44.358719 | TASK [Install git and tox]
2025-11-07 00:08:28.927908 | controller | changed
2025-11-07 00:08:28.941190 | 
2025-11-07 00:08:28.941327 | TASK [include_role : prepare-workspace]
2025-11-07 00:08:28.998320 | controller | ok
2025-11-07 00:08:29.050438 | 
2025-11-07 00:08:29.050565 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-07 00:08:29.342893 | controller | ok
2025-11-07 00:08:29.354114 | 
2025-11-07 00:08:29.354238 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-07 00:08:47.365802 | controller | Output suppressed because no_log was given
2025-11-07 00:08:47.375916 | 
2025-11-07 00:08:47.375984 | TASK [include_role : prepare-workspace-openshift]
2025-11-07 00:08:47.414754 | controller | skipping: Conditional result was False
2025-11-07 00:08:47.468022 | 
2025-11-07 00:08:47.468097 | PLAY [all:!appliance]
2025-11-07 00:08:47.483820 | 
2025-11-07 00:08:47.483903 | TASK [Run add-build-sshkey role (RSA)]
2025-11-07 00:08:47.503408 | controller | ok
2025-11-07 00:08:47.518478 | 
2025-11-07 00:08:47.518598 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-07 00:08:47.767482 | controller -> localhost | ok
2025-11-07 00:08:47.774306 | 
2025-11-07 00:08:47.774432 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-07 00:08:47.806508 | controller | ok
2025-11-07 00:08:47.830152 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-07 00:08:47.839267 | 
2025-11-07 00:08:47.839384 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-07 00:08:48.560830 | controller -> localhost | Generating public/private rsa key pair.
2025-11-07 00:08:48.561008 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_rsa.
2025-11-07 00:08:48.561037 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_rsa.pub.
2025-11-07 00:08:48.561058 | controller -> localhost | The key fingerprint is:
2025-11-07 00:08:48.561079 | controller -> localhost | SHA256:Ynw4Ij2Y/uXpQaTMlQ132D348nVSemji/oFWxdIfM9g zuul-build-sshkey
2025-11-07 00:08:48.561104 | controller -> localhost | The key's randomart image is:
2025-11-07 00:08:48.561129 | controller -> localhost | +---[RSA 2048]----+
2025-11-07 00:08:48.561153 | controller -> localhost | |      . .o.o     |
2025-11-07 00:08:48.561176 | controller -> localhost | |       =..o o oo.|
2025-11-07 00:08:48.561199 | controller -> localhost | |      + .  . o.E+|
2025-11-07 00:08:48.561222 | controller -> localhost | |   * = .  . o *oB|
2025-11-07 00:08:48.561246 | controller -> localhost | |  + B B S  + +.+.|
2025-11-07 00:08:48.561276 | controller -> localhost | | . . = +    oo   |
2025-11-07 00:08:48.561300 | controller -> localhost | |  .   o    .o .  |
2025-11-07 00:08:48.561322 | controller -> localhost | |   . o o   ..  . |
2025-11-07 00:08:48.561343 | controller -> localhost | |    ..+      ..  |
2025-11-07 00:08:48.561370 | controller -> localhost | +----[SHA256]-----+
2025-11-07 00:08:48.561422 | controller -> localhost | ok: Runtime: 0:00:00.234963
2025-11-07 00:08:48.569853 | 
2025-11-07 00:08:48.569995 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-07 00:08:48.617542 | controller | ok
2025-11-07 00:08:48.628781 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-07 00:08:48.639264 | 
2025-11-07 00:08:48.639383 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-07 00:08:48.663727 | controller | skipping: Conditional result was False
2025-11-07 00:08:48.672262 | 
2025-11-07 00:08:48.672382 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-07 00:08:49.120018 | controller | changed
2025-11-07 00:08:49.128880 | 
2025-11-07 00:08:49.129018 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-07 00:08:49.344305 | controller | ok
2025-11-07 00:08:49.350238 | 
2025-11-07 00:08:49.350309 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-07 00:08:49.966576 | controller | changed
2025-11-07 00:08:49.972702 | 
2025-11-07 00:08:49.972766 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-07 00:08:50.589137 | controller | changed
2025-11-07 00:08:50.599491 | 
2025-11-07 00:08:50.599602 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-07 00:08:50.626605 | controller | skipping: Conditional result was False
2025-11-07 00:08:50.641646 | 
2025-11-07 00:08:50.641802 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-07 00:08:51.091352 | controller -> localhost | changed
2025-11-07 00:08:51.106267 | 
2025-11-07 00:08:51.106379 | TASK [add-build-sshkey : Add back temp key]
2025-11-07 00:08:51.398993 | controller -> localhost | Identity added: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_rsa (zuul-build-sshkey)
2025-11-07 00:08:51.399196 | controller -> localhost | ok: Runtime: 0:00:00.011607
2025-11-07 00:08:51.407282 | 
2025-11-07 00:08:51.407346 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-07 00:08:51.755409 | controller | ok
2025-11-07 00:08:51.761064 | 
2025-11-07 00:08:51.761137 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-07 00:08:51.795669 | controller | skipping: Conditional result was False
2025-11-07 00:08:51.810149 | 
2025-11-07 00:08:51.810265 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-07 00:08:51.840075 | controller | ok
2025-11-07 00:08:51.857403 | 
2025-11-07 00:08:51.857511 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-07 00:08:52.120258 | controller -> localhost | ok
2025-11-07 00:08:52.128196 | 
2025-11-07 00:08:52.128306 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-07 00:08:52.149642 | controller | ok
2025-11-07 00:08:52.161330 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-07 00:08:52.168006 | 
2025-11-07 00:08:52.168082 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-07 00:08:52.447340 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-07 00:08:52.447547 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_ecdsa.
2025-11-07 00:08:52.447584 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_ecdsa.pub.
2025-11-07 00:08:52.447619 | controller -> localhost | The key fingerprint is:
2025-11-07 00:08:52.447645 | controller -> localhost | SHA256:5AkOx1NzewSKBerSQrUb5NKpr8YKwAIJhCHQTecs3pY zuul-build-sshkey
2025-11-07 00:08:52.447672 | controller -> localhost | The key's randomart image is:
2025-11-07 00:08:52.447723 | controller -> localhost | +---[ECDSA 521]---+
2025-11-07 00:08:52.447749 | controller -> localhost | |O+ o+ o.+ o..    |
2025-11-07 00:08:52.447773 | controller -> localhost | |+..=.O + + o     |
2025-11-07 00:08:52.447796 | controller -> localhost | |o o X O o . .    |
2025-11-07 00:08:52.447818 | controller -> localhost | |o. * O * . .     |
2025-11-07 00:08:52.447843 | controller -> localhost | |o.+ = E S        |
2025-11-07 00:08:52.447866 | controller -> localhost | |o  + .           |
2025-11-07 00:08:52.447888 | controller -> localhost | |..  .            |
2025-11-07 00:08:52.447910 | controller -> localhost | |. o.             |
2025-11-07 00:08:52.447935 | controller -> localhost | |.o.              |
2025-11-07 00:08:52.447958 | controller -> localhost | +----[SHA256]-----+
2025-11-07 00:08:52.448018 | controller -> localhost | ok: Runtime: 0:00:00.007859
2025-11-07 00:08:52.459813 | 
2025-11-07 00:08:52.459915 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-07 00:08:52.493452 | controller | ok
2025-11-07 00:08:52.501460 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-07 00:08:52.511404 | 
2025-11-07 00:08:52.511503 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-07 00:08:52.535857 | controller | skipping: Conditional result was False
2025-11-07 00:08:52.542302 | 
2025-11-07 00:08:52.542371 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-07 00:08:52.803219 | controller | changed
2025-11-07 00:08:52.810809 | 
2025-11-07 00:08:52.810894 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-07 00:08:53.025853 | controller | ok
2025-11-07 00:08:53.031611 | 
2025-11-07 00:08:53.031714 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-07 00:08:53.633546 | controller | changed
2025-11-07 00:08:53.641376 | 
2025-11-07 00:08:53.641489 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-07 00:08:54.277324 | controller | changed
2025-11-07 00:08:54.287924 | 
2025-11-07 00:08:54.288043 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-07 00:08:54.302667 | controller | skipping: Conditional result was False
2025-11-07 00:08:54.310587 | 
2025-11-07 00:08:54.310874 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-07 00:08:54.570083 | controller -> localhost | changed
2025-11-07 00:08:54.582549 | 
2025-11-07 00:08:54.583420 | TASK [add-build-sshkey : Add back temp key]
2025-11-07 00:08:55.039407 | controller -> localhost | Identity added: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/e0db87d48605402f94944efd1edda587_id_ecdsa (zuul-build-sshkey)
2025-11-07 00:08:55.039692 | controller -> localhost | ok: Runtime: 0:00:00.007816
2025-11-07 00:08:55.102617 | 
2025-11-07 00:08:55.102745 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-07 00:08:55.311674 | controller | ok
2025-11-07 00:08:55.321884 | 
2025-11-07 00:08:55.322027 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-07 00:08:55.363876 | controller | skipping: Conditional result was False
2025-11-07 00:08:55.385900 | 
2025-11-07 00:08:55.386003 | TASK [include_role : remove-zuul-sshkey]
2025-11-07 00:08:55.426420 | controller | skipping: Conditional result was False
2025-11-07 00:08:55.433530 | 
2025-11-07 00:08:55.433630 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-07 00:08:55.650468 | controller | ok: "logs"
2025-11-07 00:08:55.650776 | controller | ok: All items complete
2025-11-07 00:08:55.650816 | 
2025-11-07 00:08:55.837008 | controller | ok: "artifacts"
2025-11-07 00:08:56.022892 | controller | ok: "docs"
2025-11-07 00:08:56.040396 | 
2025-11-07 00:08:56.040519 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-07 00:08:56.324631 | controller | changed: "logs"
2025-11-07 00:08:56.523607 | controller | changed: "artifacts"
2025-11-07 00:08:56.702214 | controller | changed: "docs"
2025-11-07 00:08:56.743857 | 
2025-11-07 00:08:56.743979 | PLAY RECAP
2025-11-07 00:08:56.744091 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-07 00:08:56.744166 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-07 00:08:56.744194 | 
2025-11-07 00:08:56.871772 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-07 00:08:56.872934 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-07 00:08:57.633146 | 
2025-11-07 00:08:57.633324 | PLAY [all]
2025-11-07 00:08:57.658251 | 
2025-11-07 00:08:57.658464 | TASK [Install binary dependencies]
2025-11-07 00:08:57.739160 | controller | ok
2025-11-07 00:08:57.763034 | 
2025-11-07 00:08:57.763169 | TASK [bindep : Include find tasks]
2025-11-07 00:08:57.792990 | controller | ok
2025-11-07 00:08:57.800643 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-07 00:08:57.806950 | 
2025-11-07 00:08:57.807013 | TASK [bindep : Look for bindep.txt]
2025-11-07 00:08:58.252113 | controller | ok
2025-11-07 00:08:58.260746 | 
2025-11-07 00:08:58.260882 | TASK [bindep : Define bindep_file fact]
2025-11-07 00:08:58.286366 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.294900 | 
2025-11-07 00:08:58.295018 | TASK [bindep : Look for other-requirements.txt]
2025-11-07 00:08:58.540958 | controller | ok
2025-11-07 00:08:58.551710 | 
2025-11-07 00:08:58.551898 | TASK [bindep : Define bindep_file fact]
2025-11-07 00:08:58.589013 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.598648 | 
2025-11-07 00:08:58.598827 | TASK [bindep : Look for bindep fallback file]
2025-11-07 00:08:58.634248 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.645257 | 
2025-11-07 00:08:58.645397 | TASK [bindep : Define bindep_file fact]
2025-11-07 00:08:58.670588 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.679115 | 
2025-11-07 00:08:58.679238 | TASK [bindep : Include bindep tasks]
2025-11-07 00:08:58.715352 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.721561 | 
2025-11-07 00:08:58.721642 | TASK [bindep : Include install tasks]
2025-11-07 00:08:58.747115 | controller | skipping: Conditional result was False
2025-11-07 00:08:58.754238 | 
2025-11-07 00:08:58.754313 | LOOP [bindep : Include package tasks]
2025-11-07 00:08:58.811644 | 
2025-11-07 00:08:58.811856 | TASK [Run test-setup role]
2025-11-07 00:08:58.836726 | controller | ok
2025-11-07 00:08:58.864697 | 
2025-11-07 00:08:58.864817 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-07 00:08:59.063481 | controller | ok
2025-11-07 00:08:59.071419 | 
2025-11-07 00:08:59.071501 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-07 00:08:59.630830 | controller | skipping: Conditional result was False
2025-11-07 00:08:59.661217 | 
2025-11-07 00:08:59.661388 | PLAY RECAP
2025-11-07 00:08:59.661449 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-07 00:08:59.661475 | 
2025-11-07 00:08:59.814722 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-07 00:08:59.817227 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-07 00:09:00.591283 | 
2025-11-07 00:09:00.591429 | PLAY [controller]
2025-11-07 00:09:00.612167 | 
2025-11-07 00:09:00.612293 | TASK [Create the /root directory]
2025-11-07 00:09:00.974026 | controller | ok
2025-11-07 00:09:00.983606 | 
2025-11-07 00:09:00.983775 | TASK [Install glibc-langpack-en]
2025-11-07 00:09:04.961070 | controller | ok: Nothing to do
2025-11-07 00:09:04.970220 | 
2025-11-07 00:09:04.970352 | TASK [Ensure controller directory exists]
2025-11-07 00:09:05.174992 | controller | changed
2025-11-07 00:09:05.181505 | 
2025-11-07 00:09:05.181618 | TASK [Install container runtime]
2025-11-07 00:09:05.234838 | controller | ok
2025-11-07 00:09:05.282589 | 
2025-11-07 00:09:05.282724 | LOOP [ensure-podman : Find distribution installation]
2025-11-07 00:09:05.312850 | controller | ok: "/var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-07 00:09:05.331145 | controller | included: /var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-07 00:09:05.345550 | 
2025-11-07 00:09:05.345722 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-07 00:10:13.222711 | controller | changed
2025-11-07 00:10:13.243042 | 
2025-11-07 00:10:13.243213 | TASK [ensure-podman : Fetch podman version]
2025-11-07 00:10:13.783292 | controller | Client:       Podman Engine
2025-11-07 00:10:13.821828 | controller | Version:      4.6.2
2025-11-07 00:10:13.821858 | controller | API Version:  4.6.2
2025-11-07 00:10:13.821866 | controller | Go Version:   go1.19.12
2025-11-07 00:10:13.821884 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-07 00:10:13.821892 | controller | OS/Arch:      linux/amd64
2025-11-07 00:10:14.297318 | controller | ok: Runtime: 0:00:00.210187
2025-11-07 00:10:14.308617 | 
2025-11-07 00:10:14.308829 | TASK [ensure-podman : Print podman version installed]
2025-11-07 00:10:14.334866 | Podman version: Client:       Podman Engine
2025-11-07 00:10:14.335827 | Version:      4.6.2
2025-11-07 00:10:14.335872 | API Version:  4.6.2
2025-11-07 00:10:14.335907 | Go Version:   go1.19.12
2025-11-07 00:10:14.335940 | Built:        Mon Aug 28 19:38:31 2023
2025-11-07 00:10:14.335972 | OS/Arch:      linux/amd64
2025-11-07 00:10:14.345437 | 
2025-11-07 00:10:14.345547 | TASK [ensure-podman : Validate podman engine]
2025-11-07 00:10:14.881564 | controller | skipping: Conditional result was False
2025-11-07 00:10:14.890857 | 
2025-11-07 00:10:14.890998 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-07 00:10:14.906036 | controller | skipping: Conditional result was False
2025-11-07 00:10:14.923136 | 
2025-11-07 00:10:14.923278 | TASK [Ensure python3.8 is present]
2025-11-07 00:10:14.938322 | controller | skipping: Conditional result was False
2025-11-07 00:10:14.948411 | 
2025-11-07 00:10:14.948539 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-07 00:10:14.973241 | controller | ok
2025-11-07 00:10:14.999933 | 
2025-11-07 00:10:15.000385 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-07 00:10:16.400501 | controller | ok: Nothing to do
2025-11-07 00:10:16.407381 | 
2025-11-07 00:10:16.407488 | TASK [our-ensure-python : Also install python3-devel]
2025-11-07 00:10:24.642858 | controller | changed
2025-11-07 00:10:24.673132 | 
2025-11-07 00:10:24.673288 | TASK [Run ensure-virtualenv role]
2025-11-07 00:10:24.713759 | controller | ok
2025-11-07 00:10:24.751995 | 
2025-11-07 00:10:24.752143 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-07 00:10:24.962494 | controller | /usr/bin/virtualenv
2025-11-07 00:10:25.287848 | controller | ok: Runtime: 0:00:00.004860
2025-11-07 00:10:25.302171 | 
2025-11-07 00:10:25.302374 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-07 00:10:25.342301 | controller | skipping: Conditional result was False
2025-11-07 00:10:25.342731 | controller | ok: All items complete
2025-11-07 00:10:25.342811 | 
2025-11-07 00:10:25.370052 | 
2025-11-07 00:10:25.370182 | TASK [Find the full path of the Python interpreter]
2025-11-07 00:10:25.635574 | controller | /usr/bin/python3
2025-11-07 00:10:25.962538 | controller | ok
2025-11-07 00:10:25.968337 | 
2025-11-07 00:10:25.968421 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-07 00:10:26.985024 | controller | created virtual environment CPython3.11.0.final.0-64 in 536ms
2025-11-07 00:10:27.015502 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-07 00:10:27.015517 | 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)
2025-11-07 00:10:27.015532 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-07 00:10:27.015546 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-07 00:10:27.507282 | controller | changed
2025-11-07 00:10:27.514300 | 
2025-11-07 00:10:27.514404 | TASK [Set selinux package]
2025-11-07 00:10:27.545086 | controller | ok
2025-11-07 00:10:27.550645 | 
2025-11-07 00:10:27.550729 | TASK [Set selinux package (Fedora)]
2025-11-07 00:10:27.593627 | controller | ok
2025-11-07 00:10:27.602060 | 
2025-11-07 00:10:27.602149 | TASK [Install selinux into virtualenv]
2025-11-07 00:10:53.045189 | controller | Collecting selinux-please-lie-to-me
2025-11-07 00:11:05.307040 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-07 00:11:05.608122 | controller | Collecting setuptools<50.0.0
2025-11-07 00:11:05.620988 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-07 00:11:05.655478 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 26.7 MB/s eta 0:00:00
2025-11-07 00:11:05.735648 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-07 00:11:05.735855 | controller |   Attempting uninstall: setuptools
2025-11-07 00:11:05.738283 | controller |     Found existing installation: setuptools 62.6.0
2025-11-07 00:11:05.797407 | controller |     Uninstalling setuptools-62.6.0:
2025-11-07 00:11:05.805545 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-07 00:11:06.139663 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-07 00:11:17.675848 | controller |
2025-11-07 00:11:17.755955 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-07 00:11:17.755999 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-07 00:11:18.171921 | controller | ok: Runtime: 0:00:49.935834
2025-11-07 00:11:18.180456 | 
2025-11-07 00:11:18.180544 | TASK [Install pytest-forked into virtualenv]
2025-11-07 00:11:27.879223 | controller | Collecting pytest-forked
2025-11-07 00:11:40.187313 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-07 00:11:40.232802 | controller | Collecting py
2025-11-07 00:11:40.236206 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-07 00:11:40.259101 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.7 MB/s eta 0:00:00
2025-11-07 00:11:40.366908 | controller | Collecting pytest>=3.10
2025-11-07 00:11:40.370458 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-11-07 00:11:40.389099 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 25.0 MB/s eta 0:00:00
2025-11-07 00:11:40.426699 | controller | Collecting iniconfig>=1
2025-11-07 00:11:40.431118 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-07 00:11:40.483031 | controller | Collecting packaging>=20
2025-11-07 00:11:40.487130 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-07 00:11:40.495179 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.5 MB/s eta 0:00:00
2025-11-07 00:11:40.533547 | controller | Collecting pluggy<2,>=1.5
2025-11-07 00:11:40.537873 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-07 00:11:40.591358 | controller | Collecting pygments>=2.7.2
2025-11-07 00:11:40.594369 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-07 00:11:40.617756 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 59.1 MB/s eta 0:00:00
2025-11-07 00:11:40.689536 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-07 00:11:41.792352 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-11-07 00:11:41.801607 | controller |
2025-11-07 00:11:41.880412 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-07 00:11:41.880452 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-07 00:11:42.234723 | controller | ok: Runtime: 0:00:23.488414
2025-11-07 00:11:42.245256 | 
2025-11-07 00:11:42.245371 | TASK [Update pip]
2025-11-07 00:11:42.779450 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-07 00:11:52.569762 | controller | Collecting pip
2025-11-07 00:12:04.770452 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-07 00:12:04.824882 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 35.8 MB/s eta 0:00:00
2025-11-07 00:12:04.890081 | controller | Installing collected packages: pip
2025-11-07 00:12:04.890308 | controller |   Attempting uninstall: pip
2025-11-07 00:12:04.892418 | controller |     Found existing installation: pip 22.2.2
2025-11-07 00:12:05.033344 | controller |     Uninstalling pip-22.2.2:
2025-11-07 00:12:05.049243 | controller |       Successfully uninstalled pip-22.2.2
2025-11-07 00:12:05.864910 | controller | Successfully installed pip-25.3
2025-11-07 00:12:06.302387 | controller | ok: Runtime: 0:00:23.474118
2025-11-07 00:12:06.308844 | 
2025-11-07 00:12:06.308920 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-07 00:12:06.533898 | controller | changed
2025-11-07 00:12:06.545117 | 
2025-11-07 00:12:06.545349 | TASK [Install ansible into virtualenv]
2025-11-07 00:12:07.087196 | controller | Processing ./src/github.com/ansible/ansible
2025-11-07 00:12:07.090438 | controller |   Installing build dependencies: started
2025-11-07 00:12:27.647247 | controller |   Installing build dependencies: finished with status 'done'
2025-11-07 00:12:27.648293 | controller |   Getting requirements to build wheel: started
2025-11-07 00:12:28.401702 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-07 00:12:28.402642 | controller |   Preparing metadata (pyproject.toml): started
2025-11-07 00:12:28.865139 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-07 00:12:28.869947 | 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-11-07 00:12:28.873435 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-07 00:12:29.135936 | controller | ERROR
2025-11-07 00:12:29.136091 | controller | {
2025-11-07 00:12:29.136130 | controller |   "delta": "0:00:22.129699",
2025-11-07 00:12:29.136158 | controller |   "end": "2025-11-07 00:12:28.936335",
2025-11-07 00:12:29.136187 | controller |   "msg": "non-zero return code",
2025-11-07 00:12:29.136234 | controller |   "rc": 1,
2025-11-07 00:12:29.136260 | controller |   "start": "2025-11-07 00:12:06.806636"
2025-11-07 00:12:29.136284 | controller | }
failure
2025-11-07 00:12:29.138557 | 
2025-11-07 00:12:29.138662 | PLAY RECAP
2025-11-07 00:12:29.138782 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-07 00:12:29.138850 | 
2025-11-07 00:12:29.268751 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-07 00:12:29.269838 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-07 00:12:29.861749 | 
2025-11-07 00:12:29.861878 | PLAY [all]
2025-11-07 00:12:29.885387 | 
2025-11-07 00:12:29.885507 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-07 00:12:30.157573 | controller | changed: non-zero return code
2025-11-07 00:12:30.172503 | 
2025-11-07 00:12:30.172790 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-07 00:12:30.199925 | controller | skipping: Conditional result was False
2025-11-07 00:12:30.208997 | 
2025-11-07 00:12:30.209105 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-07 00:12:30.244504 | 
2025-11-07 00:12:30.244734 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-07 00:12:30.278439 | 
2025-11-07 00:12:30.278628 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-07 00:12:30.303473 | controller | skipping: Conditional result was False
2025-11-07 00:12:30.313312 | 
2025-11-07 00:12:30.313413 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-07 00:12:30.346153 | 
2025-11-07 00:12:30.346357 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-07 00:12:30.362074 | controller | skipping: Conditional result was False
2025-11-07 00:12:30.369189 | 
2025-11-07 00:12:30.369269 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-07 00:12:30.393175 | controller | skipping: Conditional result was False
2025-11-07 00:12:30.400105 | 
2025-11-07 00:12:30.400185 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-07 00:12:30.424036 | controller | skipping: Conditional result was False
2025-11-07 00:12:30.452389 | 
2025-11-07 00:12:30.452491 | PLAY RECAP
2025-11-07 00:12:30.452541 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-07 00:12:30.452569 | 
2025-11-07 00:12:30.548301 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-07 00:12:30.549204 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-07 00:12:31.176978 | 
2025-11-07 00:12:31.177110 | PLAY [all:!appliance*]
2025-11-07 00:12:31.200494 | 
2025-11-07 00:12:31.200619 | TASK [unregister the node]
2025-11-07 00:12:31.737376 | controller | skipping: Conditional result was False
2025-11-07 00:12:31.745775 | 
2025-11-07 00:12:31.745912 | TASK [include_role : fetch-output]
2025-11-07 00:12:31.780371 | controller | ok
2025-11-07 00:12:31.814008 | 
2025-11-07 00:12:31.814162 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-07 00:12:31.891296 | controller | skipping: Conditional result was False
2025-11-07 00:12:31.901635 | 
2025-11-07 00:12:31.901816 | TASK [fetch-output : Set log path for single node]
2025-11-07 00:12:31.946728 | controller | ok
2025-11-07 00:12:31.955436 | 
2025-11-07 00:12:31.955555 | LOOP [fetch-output : Ensure local output dirs]
2025-11-07 00:12:32.400044 | controller -> localhost | ok: "/var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/logs"
2025-11-07 00:12:32.701482 | controller -> localhost | changed: "/var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/artifacts"
2025-11-07 00:12:32.923873 | controller -> localhost | changed: "/var/lib/zuul/builds/e0db87d48605402f94944efd1edda587/work/docs"
2025-11-07 00:12:32.938523 | 
2025-11-07 00:12:32.938633 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-07 00:12:33.633909 | controller | changed:
2025-11-07 00:12:33.634239 | controller | .d..t...... ./
2025-11-07 00:12:33.634283 | controller | cd+++++++++ controller/
2025-11-07 00:12:33.634331 | controller | changed: All items complete
2025-11-07 00:12:33.634361 | 
2025-11-07 00:12:34.113983 | controller | changed: .d..t...... ./
2025-11-07 00:12:34.631389 | controller | changed: .d..t...... ./
2025-11-07 00:12:34.665198 | 
2025-11-07 00:12:34.665414 | TASK [include_role : fetch-output-openshift]
2025-11-07 00:12:34.693395 | controller | skipping: Conditional result was False
2025-11-07 00:12:34.700206 | 
2025-11-07 00:12:34.700280 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-07 00:12:34.748331 | controller | skipping: Conditional result was False
2025-11-07 00:12:34.758808 | controller | skipping: Conditional result was False
2025-11-07 00:12:34.804722 | 
2025-11-07 00:12:34.804848 | PLAY [localhost]
2025-11-07 00:12:34.823368 | 
2025-11-07 00:12:34.823480 | TASK [Run Zuul manifest role]
2025-11-07 00:12:34.843122 | localhost | ok
2025-11-07 00:12:34.856371 | 
2025-11-07 00:12:34.856471 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-07 00:12:35.251520 | localhost | changed
2025-11-07 00:12:35.266050 | 
2025-11-07 00:12:35.266254 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-07 00:12:35.307938 | localhost | ok
2025-11-07 00:12:35.330594 | 
2025-11-07 00:12:35.330819 | TASK [Set zuul-log-path fact]
2025-11-07 00:12:35.352560 | localhost | ok
2025-11-07 00:12:35.373947 | 
2025-11-07 00:12:35.374070 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-07 00:12:35.417197 | localhost | ok
2025-11-07 00:12:35.430138 | 
2025-11-07 00:12:35.430227 | LOOP [Run upload-logs-swift role]
2025-11-07 00:12:35.479054 | localhost | Output suppressed because no_log was given
2025-11-07 00:12:35.519385 | 
2025-11-07 00:12:35.519530 | TASK [Set zuul-log-path fact]
2025-11-07 00:12:35.555507 | localhost | skipping: Conditional result was False
2025-11-07 00:12:35.564116 | 
2025-11-07 00:12:35.564225 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-07 00:12:35.976949 | localhost -> localhost | ok: Runtime: 0:00:00.004861
2025-11-07 00:12:35.995878 | 
2025-11-07 00:12:35.996071 | TASK [upload-logs-swift : Upload logs to swift]