2025-11-15 00:06:52.778849 | Job console starting...
2025-11-15 00:06:52.790295 | Updating repositories
2025-11-15 00:06:55.854246 | Preparing job workspace
2025-11-15 00:07:00.631781 | Running Ansible setup...
2025-11-15 00:07:05.523630 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-15 00:07:06.257362 | 
2025-11-15 00:07:06.257514 | PLAY [localhost]
2025-11-15 00:07:06.267947 | 
2025-11-15 00:07:06.268074 | TASK [Gathering Facts]
2025-11-15 00:07:07.308766 | localhost | ok
2025-11-15 00:07:07.335799 | 
2025-11-15 00:07:07.335966 | TASK [Setup log path fact]
2025-11-15 00:07:07.356947 | localhost | ok
2025-11-15 00:07:07.370624 | 
2025-11-15 00:07:07.370790 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-15 00:07:07.415101 | localhost | ok
2025-11-15 00:07:07.431469 | 
2025-11-15 00:07:07.431619 | TASK [emit-job-header : Print job information]
2025-11-15 00:07:07.472801 | # Job Information
2025-11-15 00:07:07.472979 | Ansible Version: 2.15.12
2025-11-15 00:07:07.473025 | Job: ansible-test-sanity-docker-devel
2025-11-15 00:07:07.473059 | Pipeline: periodic
2025-11-15 00:07:07.473088 | Executor: ze03.softwarefactory-project.io
2025-11-15 00:07:07.473116 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-15 00:07:07.473149 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/501/ansible/501997bb42ba405abaf48960cb9cbfbc/
2025-11-15 00:07:07.473179 | Event ID: a858ce625d92420fb6078838affaf367
2025-11-15 00:07:07.479467 | 
2025-11-15 00:07:07.479613 | LOOP [emit-job-header : Print node information]
2025-11-15 00:07:07.606147 | localhost | ok:
2025-11-15 00:07:07.606332 | localhost | # Node Information
2025-11-15 00:07:07.606369 | localhost | Inventory Hostname: controller
2025-11-15 00:07:07.606397 | localhost | Hostname: np0005523222
2025-11-15 00:07:07.606424 | localhost | Username: zuul
2025-11-15 00:07:07.606454 | localhost | Distro: Fedora 37
2025-11-15 00:07:07.606480 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-15 00:07:07.606505 | localhost | Region: ca-ymq-1
2025-11-15 00:07:07.606529 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-15 00:07:07.606552 | localhost | Product Name: OpenStack Nova
2025-11-15 00:07:07.606576 | localhost | Interface IP: 162.253.55.186
2025-11-15 00:07:07.624918 | 
2025-11-15 00:07:07.625113 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-15 00:07:08.055957 | localhost -> localhost | changed
2025-11-15 00:07:08.061563 | 
2025-11-15 00:07:08.061634 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-15 00:07:08.977370 | localhost -> localhost | changed
2025-11-15 00:07:08.996787 | 
2025-11-15 00:07:08.996864 | PLAY [all:!appliance*]
2025-11-15 00:07:09.013905 | 
2025-11-15 00:07:09.013976 | TASK [include_role : start-zuul-console]
2025-11-15 00:07:09.034418 | controller | ok
2025-11-15 00:07:09.048815 | 
2025-11-15 00:07:09.048888 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-15 00:07:09.430001 | controller | ok
2025-11-15 00:07:09.457457 | 
2025-11-15 00:07:09.457629 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-15 00:07:32.159632 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-15 00:07:32.174214 | 
2025-11-15 00:07:32.174382 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-15 00:07:32.722805 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.738152 | 
2025-11-15 00:07:32.738614 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-15 00:07:32.767155 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.785108 | 
2025-11-15 00:07:32.785306 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-15 00:07:32.813069 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.829254 | 
2025-11-15 00:07:32.829459 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-15 00:07:32.857746 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.868675 | 
2025-11-15 00:07:32.868851 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-15 00:07:32.894460 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.910169 | 
2025-11-15 00:07:32.910319 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-15 00:07:32.935959 | controller | skipping: Conditional result was False
2025-11-15 00:07:32.951511 | 
2025-11-15 00:07:32.951616 | TASK [Disable Fedora Modular]
2025-11-15 00:07:33.182901 | controller | changed
2025-11-15 00:07:33.191541 | 
2025-11-15 00:07:33.191634 | TASK [Enable EPEL]
2025-11-15 00:07:33.226571 | controller | skipping: Conditional result was False
2025-11-15 00:07:33.235499 | 
2025-11-15 00:07:33.235598 | TASK [Register the RHEL node]
2025-11-15 00:07:33.793051 | 
2025-11-15 00:07:33.793476 | TASK [Show the subscription-manager status]
2025-11-15 00:07:34.365359 | controller | skipping: Conditional result was False
2025-11-15 00:07:34.375611 | 
2025-11-15 00:07:34.375761 | TASK [Enable EPEL on RHEL]
2025-11-15 00:07:34.917321 | controller | skipping: Conditional result was False
2025-11-15 00:07:34.932166 | 
2025-11-15 00:07:34.932329 | TASK [Install git and tox]
2025-11-15 00:08:21.146113 | controller | changed
2025-11-15 00:08:21.160215 | 
2025-11-15 00:08:21.160398 | TASK [include_role : prepare-workspace]
2025-11-15 00:08:21.190019 | controller | ok
2025-11-15 00:08:21.256103 | 
2025-11-15 00:08:21.256217 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-15 00:08:21.495093 | controller | ok
2025-11-15 00:08:21.509101 | 
2025-11-15 00:08:21.509826 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-15 00:08:35.173522 | controller | Output suppressed because no_log was given
2025-11-15 00:08:35.197752 | 
2025-11-15 00:08:35.197886 | TASK [include_role : prepare-workspace-openshift]
2025-11-15 00:08:35.225059 | controller | skipping: Conditional result was False
2025-11-15 00:08:35.267935 | 
2025-11-15 00:08:35.268057 | PLAY [all:!appliance]
2025-11-15 00:08:35.289751 | 
2025-11-15 00:08:35.289925 | TASK [Run add-build-sshkey role (RSA)]
2025-11-15 00:08:35.322289 | controller | ok
2025-11-15 00:08:35.345963 | 
2025-11-15 00:08:35.346090 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-15 00:08:35.668939 | controller -> localhost | ok
2025-11-15 00:08:35.683809 | 
2025-11-15 00:08:35.684039 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-15 00:08:35.714935 | controller | ok
2025-11-15 00:08:35.749880 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-15 00:08:35.762212 | 
2025-11-15 00:08:35.762340 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-15 00:08:36.378528 | controller -> localhost | Generating public/private rsa key pair.
2025-11-15 00:08:36.378963 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_rsa.
2025-11-15 00:08:36.379032 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_rsa.pub.
2025-11-15 00:08:36.379081 | controller -> localhost | The key fingerprint is:
2025-11-15 00:08:36.379126 | controller -> localhost | SHA256:sbs26+Aplkajckf0jsBKCrSvW4amDD5UzZBMX3Juc9s zuul-build-sshkey
2025-11-15 00:08:36.379171 | controller -> localhost | The key's randomart image is:
2025-11-15 00:08:36.379214 | controller -> localhost | +---[RSA 2048]----+
2025-11-15 00:08:36.379255 | controller -> localhost | |  o... o         |
2025-11-15 00:08:36.379298 | controller -> localhost | |   +. =          |
2025-11-15 00:08:36.379339 | controller -> localhost | |    +. +..       |
2025-11-15 00:08:36.379381 | controller -> localhost | | . ..o. ooo      |
2025-11-15 00:08:36.379422 | controller -> localhost | |..o. .  S. E     |
2025-11-15 00:08:36.379479 | controller -> localhost | |.++ + .  .       |
2025-11-15 00:08:36.379533 | controller -> localhost | |*+.B =. .        |
2025-11-15 00:08:36.379578 | controller -> localhost | |X.=.B..oo.       |
2025-11-15 00:08:36.379620 | controller -> localhost | |.B++ .oo+o       |
2025-11-15 00:08:36.379668 | controller -> localhost | +----[SHA256]-----+
2025-11-15 00:08:36.379806 | controller -> localhost | ok: Runtime: 0:00:00.119237
2025-11-15 00:08:36.396208 | 
2025-11-15 00:08:36.396401 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-15 00:08:36.438159 | controller | ok
2025-11-15 00:08:36.456744 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-15 00:08:36.469605 | 
2025-11-15 00:08:36.469713 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-15 00:08:36.495265 | controller | skipping: Conditional result was False
2025-11-15 00:08:36.512515 | 
2025-11-15 00:08:36.512661 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-15 00:08:36.971195 | controller | changed
2025-11-15 00:08:36.986308 | 
2025-11-15 00:08:36.986497 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-15 00:08:37.211108 | controller | ok
2025-11-15 00:08:37.224838 | 
2025-11-15 00:08:37.224981 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-15 00:08:37.895027 | controller | changed
2025-11-15 00:08:37.903431 | 
2025-11-15 00:08:37.903524 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-15 00:08:38.533003 | controller | changed
2025-11-15 00:08:38.546527 | 
2025-11-15 00:08:38.546700 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-15 00:08:38.574095 | controller | skipping: Conditional result was False
2025-11-15 00:08:38.584513 | 
2025-11-15 00:08:38.584657 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-15 00:08:38.927904 | controller -> localhost | changed
2025-11-15 00:08:38.940000 | 
2025-11-15 00:08:38.940098 | TASK [add-build-sshkey : Add back temp key]
2025-11-15 00:08:39.198376 | controller -> localhost | Identity added: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_rsa (zuul-build-sshkey)
2025-11-15 00:08:39.198636 | controller -> localhost | ok: Runtime: 0:00:00.007239
2025-11-15 00:08:39.205655 | 
2025-11-15 00:08:39.205756 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-15 00:08:39.504836 | controller | ok
2025-11-15 00:08:39.514442 | 
2025-11-15 00:08:39.514540 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-15 00:08:39.560078 | controller | skipping: Conditional result was False
2025-11-15 00:08:39.586758 | 
2025-11-15 00:08:39.586978 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-15 00:08:39.626336 | controller | ok
2025-11-15 00:08:39.655965 | 
2025-11-15 00:08:39.656203 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-15 00:08:39.932900 | controller -> localhost | ok
2025-11-15 00:08:39.946934 | 
2025-11-15 00:08:39.947085 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-15 00:08:39.989056 | controller | ok
2025-11-15 00:08:40.012850 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-15 00:08:40.022316 | 
2025-11-15 00:08:40.022413 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-15 00:08:40.349494 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-15 00:08:40.349720 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_ecdsa.
2025-11-15 00:08:40.349806 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_ecdsa.pub.
2025-11-15 00:08:40.349854 | controller -> localhost | The key fingerprint is:
2025-11-15 00:08:40.349887 | controller -> localhost | SHA256:TgxQllNUcrMRLLqGs3uOp6XYzDPjIO/Wk+TJNwbKXvg zuul-build-sshkey
2025-11-15 00:08:40.349920 | controller -> localhost | The key's randomart image is:
2025-11-15 00:08:40.349949 | controller -> localhost | +---[ECDSA 521]---+
2025-11-15 00:08:40.349977 | controller -> localhost | |    ..o++o*.     |
2025-11-15 00:08:40.350006 | controller -> localhost | |     oo .o.+     |
2025-11-15 00:08:40.350033 | controller -> localhost | |      .o ..      |
2025-11-15 00:08:40.350061 | controller -> localhost | |      .o         |
2025-11-15 00:08:40.350087 | controller -> localhost | |     . .S        |
2025-11-15 00:08:40.350114 | controller -> localhost | |   .= oo         |
2025-11-15 00:08:40.350140 | controller -> localhost | |..o*.B. .        |
2025-11-15 00:08:40.350167 | controller -> localhost | | o+O%+*          |
2025-11-15 00:08:40.350193 | controller -> localhost | | +=.E&..         |
2025-11-15 00:08:40.350232 | controller -> localhost | +----[SHA256]-----+
2025-11-15 00:08:40.350300 | controller -> localhost | ok: Runtime: 0:00:00.014940
2025-11-15 00:08:40.361268 | 
2025-11-15 00:08:40.361380 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-15 00:08:40.385826 | controller | ok
2025-11-15 00:08:40.397373 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-15 00:08:40.411891 | 
2025-11-15 00:08:40.412000 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-15 00:08:40.437646 | controller | skipping: Conditional result was False
2025-11-15 00:08:40.447916 | 
2025-11-15 00:08:40.448067 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-15 00:08:40.722221 | controller | changed
2025-11-15 00:08:40.732479 | 
2025-11-15 00:08:40.732580 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-15 00:08:40.968619 | controller | ok
2025-11-15 00:08:40.980107 | 
2025-11-15 00:08:40.980241 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-15 00:08:41.637315 | controller | changed
2025-11-15 00:08:41.651531 | 
2025-11-15 00:08:41.651671 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-15 00:08:42.321610 | controller | changed
2025-11-15 00:08:42.335505 | 
2025-11-15 00:08:42.335688 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-15 00:08:42.365717 | controller | skipping: Conditional result was False
2025-11-15 00:08:42.381804 | 
2025-11-15 00:08:42.381991 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-15 00:08:42.703049 | controller -> localhost | changed
2025-11-15 00:08:42.737789 | 
2025-11-15 00:08:42.738019 | TASK [add-build-sshkey : Add back temp key]
2025-11-15 00:08:43.041957 | controller -> localhost | Identity added: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/501997bb42ba405abaf48960cb9cbfbc_id_ecdsa (zuul-build-sshkey)
2025-11-15 00:08:43.042206 | controller -> localhost | ok: Runtime: 0:00:00.007390
2025-11-15 00:08:43.049500 | 
2025-11-15 00:08:43.049561 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-15 00:08:43.257708 | controller | ok
2025-11-15 00:08:43.271465 | 
2025-11-15 00:08:43.271628 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-15 00:08:43.320451 | controller | skipping: Conditional result was False
2025-11-15 00:08:43.346032 | 
2025-11-15 00:08:43.346207 | TASK [include_role : remove-zuul-sshkey]
2025-11-15 00:08:43.374272 | controller | skipping: Conditional result was False
2025-11-15 00:08:43.391499 | 
2025-11-15 00:08:43.391672 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-15 00:08:43.636828 | controller | ok: "logs"
2025-11-15 00:08:43.637402 | controller | ok: All items complete
2025-11-15 00:08:43.637467 | 
2025-11-15 00:08:43.821647 | controller | ok: "artifacts"
2025-11-15 00:08:44.012084 | controller | ok: "docs"
2025-11-15 00:08:44.033740 | 
2025-11-15 00:08:44.033960 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-15 00:08:44.281531 | controller | changed: "logs"
2025-11-15 00:08:44.477982 | controller | changed: "artifacts"
2025-11-15 00:08:44.673620 | controller | changed: "docs"
2025-11-15 00:08:44.744798 | 
2025-11-15 00:08:44.744946 | PLAY RECAP
2025-11-15 00:08:44.745022 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-15 00:08:44.745068 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-15 00:08:44.745100 | 
2025-11-15 00:08:44.874917 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-15 00:08:44.875783 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-15 00:08:45.489413 | 
2025-11-15 00:08:45.489550 | PLAY [all]
2025-11-15 00:08:45.517444 | 
2025-11-15 00:08:45.517587 | TASK [Install binary dependencies]
2025-11-15 00:08:45.589029 | controller | ok
2025-11-15 00:08:45.610549 | 
2025-11-15 00:08:45.610674 | TASK [bindep : Include find tasks]
2025-11-15 00:08:45.650389 | controller | ok
2025-11-15 00:08:45.658928 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-15 00:08:45.665392 | 
2025-11-15 00:08:45.665458 | TASK [bindep : Look for bindep.txt]
2025-11-15 00:08:46.040347 | controller | ok
2025-11-15 00:08:46.048507 | 
2025-11-15 00:08:46.048605 | TASK [bindep : Define bindep_file fact]
2025-11-15 00:08:46.074568 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.093663 | 
2025-11-15 00:08:46.093857 | TASK [bindep : Look for other-requirements.txt]
2025-11-15 00:08:46.323131 | controller | ok
2025-11-15 00:08:46.335488 | 
2025-11-15 00:08:46.335636 | TASK [bindep : Define bindep_file fact]
2025-11-15 00:08:46.363161 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.376802 | 
2025-11-15 00:08:46.377015 | TASK [bindep : Look for bindep fallback file]
2025-11-15 00:08:46.404445 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.420333 | 
2025-11-15 00:08:46.420494 | TASK [bindep : Define bindep_file fact]
2025-11-15 00:08:46.448793 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.462276 | 
2025-11-15 00:08:46.462453 | TASK [bindep : Include bindep tasks]
2025-11-15 00:08:46.489325 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.503224 | 
2025-11-15 00:08:46.503420 | TASK [bindep : Include install tasks]
2025-11-15 00:08:46.530631 | controller | skipping: Conditional result was False
2025-11-15 00:08:46.544408 | 
2025-11-15 00:08:46.544567 | LOOP [bindep : Include package tasks]
2025-11-15 00:08:46.617559 | 
2025-11-15 00:08:46.617919 | TASK [Run test-setup role]
2025-11-15 00:08:46.654848 | controller | ok
2025-11-15 00:08:46.680600 | 
2025-11-15 00:08:46.680697 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-15 00:08:46.886014 | controller | ok
2025-11-15 00:08:46.901111 | 
2025-11-15 00:08:46.901409 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-15 00:08:47.453139 | controller | skipping: Conditional result was False
2025-11-15 00:08:47.512146 | 
2025-11-15 00:08:47.512292 | PLAY RECAP
2025-11-15 00:08:47.512371 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-15 00:08:47.512419 | 
2025-11-15 00:08:47.610513 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-15 00:08:47.612183 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-15 00:08:48.179511 | 
2025-11-15 00:08:48.179642 | PLAY [controller]
2025-11-15 00:08:48.199923 | 
2025-11-15 00:08:48.200071 | TASK [Create the /root directory]
2025-11-15 00:08:48.629795 | controller | ok
2025-11-15 00:08:48.643447 | 
2025-11-15 00:08:48.643617 | TASK [Install glibc-langpack-en]
2025-11-15 00:08:52.656634 | controller | ok: Nothing to do
2025-11-15 00:08:52.675840 | 
2025-11-15 00:08:52.676118 | TASK [Ensure controller directory exists]
2025-11-15 00:08:52.919837 | controller | changed
2025-11-15 00:08:52.930633 | 
2025-11-15 00:08:52.930748 | TASK [Install container runtime]
2025-11-15 00:08:52.984158 | controller | ok
2025-11-15 00:08:53.036055 | 
2025-11-15 00:08:53.036200 | LOOP [ensure-podman : Find distribution installation]
2025-11-15 00:08:53.068847 | controller | ok: "/var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-15 00:08:53.078414 | controller | included: /var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-15 00:08:53.086310 | 
2025-11-15 00:08:53.086409 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-15 00:10:03.272163 | controller | changed
2025-11-15 00:10:03.278509 | 
2025-11-15 00:10:03.278570 | TASK [ensure-podman : Fetch podman version]
2025-11-15 00:10:03.791548 | controller | Client:       Podman Engine
2025-11-15 00:10:03.814782 | controller | Version:      4.6.2
2025-11-15 00:10:03.814818 | controller | API Version:  4.6.2
2025-11-15 00:10:03.814826 | controller | Go Version:   go1.19.12
2025-11-15 00:10:03.814843 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-15 00:10:03.814851 | controller | OS/Arch:      linux/amd64
2025-11-15 00:10:03.862421 | controller | ok: Runtime: 0:00:00.172877
2025-11-15 00:10:03.877451 | 
2025-11-15 00:10:03.877648 | TASK [ensure-podman : Print podman version installed]
2025-11-15 00:10:03.900544 | Podman version: Client:       Podman Engine
2025-11-15 00:10:03.900693 | Version:      4.6.2
2025-11-15 00:10:03.900758 | API Version:  4.6.2
2025-11-15 00:10:03.900790 | Go Version:   go1.19.12
2025-11-15 00:10:03.900817 | Built:        Mon Aug 28 19:38:31 2023
2025-11-15 00:10:03.900843 | OS/Arch:      linux/amd64
2025-11-15 00:10:03.908797 | 
2025-11-15 00:10:03.908877 | TASK [ensure-podman : Validate podman engine]
2025-11-15 00:10:04.448060 | controller | skipping: Conditional result was False
2025-11-15 00:10:04.454940 | 
2025-11-15 00:10:04.455013 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-15 00:10:04.478658 | controller | skipping: Conditional result was False
2025-11-15 00:10:04.490209 | 
2025-11-15 00:10:04.490312 | TASK [Ensure python3.8 is present]
2025-11-15 00:10:04.504703 | controller | skipping: Conditional result was False
2025-11-15 00:10:04.513442 | 
2025-11-15 00:10:04.514039 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-15 00:10:04.537133 | controller | ok
2025-11-15 00:10:04.566306 | 
2025-11-15 00:10:04.566443 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-15 00:10:05.924022 | controller | ok: Nothing to do
2025-11-15 00:10:05.935717 | 
2025-11-15 00:10:05.935892 | TASK [our-ensure-python : Also install python3-devel]
2025-11-15 00:10:17.093844 | controller | changed
2025-11-15 00:10:17.120288 | 
2025-11-15 00:10:17.120441 | TASK [Run ensure-virtualenv role]
2025-11-15 00:10:17.149347 | controller | ok
2025-11-15 00:10:17.210503 | 
2025-11-15 00:10:17.210629 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-15 00:10:17.441718 | controller | /usr/bin/virtualenv
2025-11-15 00:10:17.771098 | controller | ok: Runtime: 0:00:00.004831
2025-11-15 00:10:17.784100 | 
2025-11-15 00:10:17.784232 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-15 00:10:17.824381 | controller | skipping: Conditional result was False
2025-11-15 00:10:17.824854 | controller | ok: All items complete
2025-11-15 00:10:17.824921 | 
2025-11-15 00:10:17.855910 | 
2025-11-15 00:10:17.856065 | TASK [Find the full path of the Python interpreter]
2025-11-15 00:10:18.069612 | controller | /usr/bin/python3
2025-11-15 00:10:18.402576 | controller | ok
2025-11-15 00:10:18.414791 | 
2025-11-15 00:10:18.414963 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-15 00:10:19.308150 | controller | created virtual environment CPython3.11.0.final.0-64 in 460ms
2025-11-15 00:10:19.325644 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-15 00:10:19.325660 | 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-15 00:10:19.325669 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-15 00:10:19.325681 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-15 00:10:19.465983 | controller | changed
2025-11-15 00:10:19.481663 | 
2025-11-15 00:10:19.481856 | TASK [Set selinux package]
2025-11-15 00:10:19.525003 | controller | ok
2025-11-15 00:10:19.537544 | 
2025-11-15 00:10:19.537624 | TASK [Set selinux package (Fedora)]
2025-11-15 00:10:19.569772 | controller | ok
2025-11-15 00:10:19.576980 | 
2025-11-15 00:10:19.577081 | TASK [Install selinux into virtualenv]
2025-11-15 00:10:33.093662 | controller | Collecting selinux-please-lie-to-me
2025-11-15 00:10:45.320155 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-15 00:10:45.612273 | controller | Collecting setuptools<50.0.0
2025-11-15 00:10:45.617936 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-15 00:10:45.654264 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 24.8 MB/s eta 0:00:00
2025-11-15 00:10:45.734184 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-15 00:10:45.734417 | controller |   Attempting uninstall: setuptools
2025-11-15 00:10:45.736777 | controller |     Found existing installation: setuptools 62.6.0
2025-11-15 00:10:45.795954 | controller |     Uninstalling setuptools-62.6.0:
2025-11-15 00:10:45.803798 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-15 00:10:46.149680 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-15 00:10:57.688796 | controller |
2025-11-15 00:10:57.768735 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-15 00:10:57.768778 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-15 00:10:58.147097 | controller | ok: Runtime: 0:00:37.979827
2025-11-15 00:10:58.160590 | 
2025-11-15 00:10:58.160864 | TASK [Install pytest-forked into virtualenv]
2025-11-15 00:11:09.972724 | controller | Collecting pytest-forked
2025-11-15 00:11:22.311920 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-15 00:11:22.359241 | controller | Collecting py
2025-11-15 00:11:22.362713 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-15 00:11:22.384383 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.2 MB/s eta 0:00:00
2025-11-15 00:11:22.496315 | controller | Collecting pytest>=3.10
2025-11-15 00:11:22.499976 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-15 00:11:22.515740 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 29.4 MB/s eta 0:00:00
2025-11-15 00:11:22.549927 | controller | Collecting iniconfig>=1.0.1
2025-11-15 00:11:22.553318 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-15 00:11:22.589722 | controller | Collecting packaging>=22
2025-11-15 00:11:22.593949 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-15 00:11:22.599091 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 18.9 MB/s eta 0:00:00
2025-11-15 00:11:22.634853 | controller | Collecting pluggy<2,>=1.5
2025-11-15 00:11:22.637973 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-15 00:11:22.685998 | controller | Collecting pygments>=2.7.2
2025-11-15 00:11:22.690071 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-15 00:11:22.709869 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 68.8 MB/s eta 0:00:00
2025-11-15 00:11:22.788165 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-15 00:11:23.875280 | 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.1 pytest-forked-1.6.0
2025-11-15 00:11:23.884000 | controller |
2025-11-15 00:11:23.952037 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-15 00:11:23.952069 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-15 00:11:24.259614 | controller | ok: Runtime: 0:00:25.528463
2025-11-15 00:11:24.272849 | 
2025-11-15 00:11:24.273010 | TASK [Update pip]
2025-11-15 00:11:24.787109 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-15 00:11:49.157971 | controller | Collecting pip
2025-11-15 00:12:01.356342 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-15 00:12:01.418503 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.4 MB/s eta 0:00:00
2025-11-15 00:12:01.487119 | controller | Installing collected packages: pip
2025-11-15 00:12:01.487283 | controller |   Attempting uninstall: pip
2025-11-15 00:12:01.489498 | controller |     Found existing installation: pip 22.2.2
2025-11-15 00:12:01.628752 | controller |     Uninstalling pip-22.2.2:
2025-11-15 00:12:01.643900 | controller |       Successfully uninstalled pip-22.2.2
2025-11-15 00:12:02.438363 | controller | Successfully installed pip-25.3
2025-11-15 00:12:02.636815 | controller | ok: Runtime: 0:00:38.019615
2025-11-15 00:12:02.649926 | 
2025-11-15 00:12:02.650080 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-15 00:12:02.863376 | controller | changed
2025-11-15 00:12:02.877602 | 
2025-11-15 00:12:02.877783 | TASK [Install ansible into virtualenv]
2025-11-15 00:12:03.387852 | controller | Processing ./src/github.com/ansible/ansible
2025-11-15 00:12:03.391094 | controller |   Installing build dependencies: started
2025-11-15 00:12:26.486423 | controller |   Installing build dependencies: finished with status 'done'
2025-11-15 00:12:26.487101 | controller |   Getting requirements to build wheel: started
2025-11-15 00:12:27.223135 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-15 00:12:27.224434 | controller |   Preparing metadata (pyproject.toml): started
2025-11-15 00:12:27.693474 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-15 00:12:27.696126 | 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-15 00:12:27.698683 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-15 00:12:27.947475 | controller | ERROR
2025-11-15 00:12:27.948232 | controller | {
2025-11-15 00:12:27.948309 | controller |   "delta": "0:00:24.660147",
2025-11-15 00:12:27.948354 | controller |   "end": "2025-11-15 00:12:27.772203",
2025-11-15 00:12:27.948404 | controller |   "msg": "non-zero return code",
2025-11-15 00:12:27.948493 | controller |   "rc": 1,
2025-11-15 00:12:27.948557 | controller |   "start": "2025-11-15 00:12:03.112056"
2025-11-15 00:12:27.948610 | controller | }
failure
2025-11-15 00:12:27.952236 | 
2025-11-15 00:12:27.952347 | PLAY RECAP
2025-11-15 00:12:27.952445 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-15 00:12:27.952488 | 
2025-11-15 00:12:28.198694 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-15 00:12:28.200047 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-15 00:12:28.837746 | 
2025-11-15 00:12:28.837894 | PLAY [all]
2025-11-15 00:12:28.860835 | 
2025-11-15 00:12:28.860939 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-15 00:12:29.144961 | controller | changed: non-zero return code
2025-11-15 00:12:29.158506 | 
2025-11-15 00:12:29.158618 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-15 00:12:29.183475 | controller | skipping: Conditional result was False
2025-11-15 00:12:29.192176 | 
2025-11-15 00:12:29.192278 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-15 00:12:29.233122 | 
2025-11-15 00:12:29.233316 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-15 00:12:29.272578 | 
2025-11-15 00:12:29.272905 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-15 00:12:29.288602 | controller | skipping: Conditional result was False
2025-11-15 00:12:29.298946 | 
2025-11-15 00:12:29.299035 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-15 00:12:29.336372 | 
2025-11-15 00:12:29.336556 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-15 00:12:29.351470 | controller | skipping: Conditional result was False
2025-11-15 00:12:29.360259 | 
2025-11-15 00:12:29.360352 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-15 00:12:29.375029 | controller | skipping: Conditional result was False
2025-11-15 00:12:29.383823 | 
2025-11-15 00:12:29.383913 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-15 00:12:29.398721 | controller | skipping: Conditional result was False
2025-11-15 00:12:29.437023 | 
2025-11-15 00:12:29.437114 | PLAY RECAP
2025-11-15 00:12:29.437159 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-15 00:12:29.437180 | 
2025-11-15 00:12:29.533434 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-15 00:12:29.534359 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-15 00:12:30.120360 | 
2025-11-15 00:12:30.120471 | PLAY [all:!appliance*]
2025-11-15 00:12:30.142291 | 
2025-11-15 00:12:30.142375 | TASK [unregister the node]
2025-11-15 00:12:30.674098 | controller | skipping: Conditional result was False
2025-11-15 00:12:30.687593 | 
2025-11-15 00:12:30.687834 | TASK [include_role : fetch-output]
2025-11-15 00:12:30.737402 | controller | ok
2025-11-15 00:12:30.772325 | 
2025-11-15 00:12:30.772477 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-15 00:12:30.848908 | controller | skipping: Conditional result was False
2025-11-15 00:12:30.862854 | 
2025-11-15 00:12:30.863006 | TASK [fetch-output : Set log path for single node]
2025-11-15 00:12:30.929240 | controller | ok
2025-11-15 00:12:30.944234 | 
2025-11-15 00:12:30.944394 | LOOP [fetch-output : Ensure local output dirs]
2025-11-15 00:12:31.429552 | controller -> localhost | ok: "/var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/logs"
2025-11-15 00:12:31.699215 | controller -> localhost | changed: "/var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/artifacts"
2025-11-15 00:12:31.962795 | controller -> localhost | changed: "/var/lib/zuul/builds/501997bb42ba405abaf48960cb9cbfbc/work/docs"
2025-11-15 00:12:31.990468 | 
2025-11-15 00:12:31.990694 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-15 00:12:32.807264 | controller | changed:
2025-11-15 00:12:32.807631 | controller | .d..t...... ./
2025-11-15 00:12:32.807676 | controller | cd+++++++++ controller/
2025-11-15 00:12:32.807785 | controller | changed: All items complete
2025-11-15 00:12:32.807837 | 
2025-11-15 00:12:33.315596 | controller | changed: .d..t...... ./
2025-11-15 00:12:33.878521 | controller | changed: .d..t...... ./
2025-11-15 00:12:33.915156 | 
2025-11-15 00:12:33.915495 | TASK [include_role : fetch-output-openshift]
2025-11-15 00:12:33.941994 | controller | skipping: Conditional result was False
2025-11-15 00:12:33.951760 | 
2025-11-15 00:12:33.951872 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-15 00:12:34.005178 | controller | skipping: Conditional result was False
2025-11-15 00:12:34.016592 | controller | skipping: Conditional result was False
2025-11-15 00:12:34.070501 | 
2025-11-15 00:12:34.070603 | PLAY [localhost]
2025-11-15 00:12:34.090314 | 
2025-11-15 00:12:34.090441 | TASK [Run Zuul manifest role]
2025-11-15 00:12:34.111607 | localhost | ok
2025-11-15 00:12:34.131506 | 
2025-11-15 00:12:34.131615 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-15 00:12:34.510329 | localhost | changed
2025-11-15 00:12:34.515017 | 
2025-11-15 00:12:34.515080 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-15 00:12:34.543539 | localhost | ok
2025-11-15 00:12:34.552097 | 
2025-11-15 00:12:34.552183 | TASK [Set zuul-log-path fact]
2025-11-15 00:12:34.571356 | localhost | ok
2025-11-15 00:12:34.584988 | 
2025-11-15 00:12:34.585077 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-15 00:12:34.613581 | localhost | ok
2025-11-15 00:12:34.622055 | 
2025-11-15 00:12:34.622118 | LOOP [Run upload-logs-swift role]
2025-11-15 00:12:34.655986 | localhost | Output suppressed because no_log was given
2025-11-15 00:12:34.682368 | 
2025-11-15 00:12:34.682458 | TASK [Set zuul-log-path fact]
2025-11-15 00:12:34.718454 | localhost | skipping: Conditional result was False
2025-11-15 00:12:34.757485 | 
2025-11-15 00:12:34.757620 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-15 00:12:35.190094 | localhost -> localhost | ok: Runtime: 0:00:00.007021
2025-11-15 00:12:35.207919 | 
2025-11-15 00:12:35.208397 | TASK [upload-logs-swift : Upload logs to swift]