2026-03-11 19:08:48.254512 | Job console starting...
2026-03-11 19:08:48.453873 | Updating repositories
2026-03-11 19:08:48.479056 | Preparing job workspace
2026-03-11 19:08:55.238708 | Running Ansible setup...
2026-03-11 19:08:58.769411 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-11 19:08:59.231321 | 
2026-03-11 19:08:59.231409 | PLAY [localhost]
2026-03-11 19:08:59.239116 | 
2026-03-11 19:08:59.239180 | TASK [Gathering Facts]
2026-03-11 19:08:59.992503 | localhost | ok
2026-03-11 19:09:00.005600 | 
2026-03-11 19:09:00.005682 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-03-11 19:09:00.292444 | localhost -> localhost | changed
2026-03-11 19:09:00.297298 | 
2026-03-11 19:09:00.297368 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-03-11 19:09:00.921494 | localhost -> localhost | changed
2026-03-11 19:09:00.929008 | 
2026-03-11 19:09:00.929077 | TASK [Setup log path fact]
2026-03-11 19:09:00.945334 | localhost | ok
2026-03-11 19:09:00.954987 | 
2026-03-11 19:09:00.955047 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-11 19:09:00.972168 | localhost | ok
2026-03-11 19:09:00.979142 | 
2026-03-11 19:09:00.979206 | TASK [emit-job-header : Print job information]
2026-03-11 19:09:01.005757 | # Job Information
2026-03-11 19:09:01.005873 | Ansible Version: 2.15.12
2026-03-11 19:09:01.005902 | Job: cifmw-molecule-reproducer
2026-03-11 19:09:01.005925 | Pipeline: github-check
2026-03-11 19:09:01.005945 | Executor: ibm-bm3-ze.softwarefactory-project.io
2026-03-11 19:09:01.005963 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3739
2026-03-11 19:09:01.005984 | Log URL (when completed): https://logserver.rdoproject.org/035/rdoproject.org/035b126cee4e4e759d8cbe4da0f20dc5/
2026-03-11 19:09:01.006003 | Event ID: 85e59850-1d7d-11f1-8349-35842047424b
2026-03-11 19:09:01.009663 | 
2026-03-11 19:09:01.009730 | LOOP [emit-job-header : Print node information]
2026-03-11 19:09:01.086062 | localhost | ok:
2026-03-11 19:09:01.086195 | localhost | # Node Information
2026-03-11 19:09:01.086224 | localhost | Inventory Hostname: controller
2026-03-11 19:09:01.086248 | localhost | Hostname: np0005644745
2026-03-11 19:09:01.086288 | localhost | Username: zuul
2026-03-11 19:09:01.086314 | localhost | Distro: CentOS 9
2026-03-11 19:09:01.086333 | localhost | Provider: ibm-bm3-nodepool
2026-03-11 19:09:01.086350 | localhost | Region: regionOne
2026-03-11 19:09:01.086367 | localhost | Label: centos-9-stream-crc-2-48-0-xxl-ibm
2026-03-11 19:09:01.086384 | localhost | Product Name: OpenStack Compute
2026-03-11 19:09:01.086401 | localhost | Interface IP: 192.168.25.47
2026-03-11 19:09:01.110630 | 
2026-03-11 19:09:01.110704 | PLAY [all]
2026-03-11 19:09:01.116294 | 
2026-03-11 19:09:01.116353 | TASK [Gather network facts]
2026-03-11 19:09:01.560994 | controller | ok
2026-03-11 19:09:01.574790 | 
2026-03-11 19:09:01.574851 | TASK [include_role : start-zuul-console]
2026-03-11 19:09:01.593315 | controller | ok
2026-03-11 19:09:01.604106 | 
2026-03-11 19:09:01.604171 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-03-11 19:09:01.965149 | controller | ok
2026-03-11 19:09:01.974686 | 
2026-03-11 19:09:01.974779 | TASK [include_role : add-build-sshkey]
2026-03-11 19:09:01.992444 | controller | ok
2026-03-11 19:09:02.008650 | 
2026-03-11 19:09:02.008737 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-03-11 19:09:02.183456 | controller -> localhost | ok
2026-03-11 19:09:02.188191 | 
2026-03-11 19:09:02.188251 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-03-11 19:09:02.206156 | controller | ok
2026-03-11 19:09:02.217199 | controller | included: /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-03-11 19:09:02.222507 | 
2026-03-11 19:09:02.222574 | TASK [add-build-sshkey : Create Temp SSH key]
2026-03-11 19:09:02.721974 | controller -> localhost | Generating public/private rsa key pair.
2026-03-11 19:09:02.722147 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/035b126cee4e4e759d8cbe4da0f20dc5_id_rsa.
2026-03-11 19:09:02.722178 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/035b126cee4e4e759d8cbe4da0f20dc5_id_rsa.pub.
2026-03-11 19:09:02.722202 | controller -> localhost | The key fingerprint is:
2026-03-11 19:09:02.722222 | controller -> localhost | SHA256:Iu0NIuZtmsPSBSVSvE8S43tEzbpC9y3RG6vS5eobyxA zuul-build-sshkey
2026-03-11 19:09:02.722242 | controller -> localhost | The key's randomart image is:
2026-03-11 19:09:02.722261 | controller -> localhost | +---[RSA 3072]----+
2026-03-11 19:09:02.722303 | controller -> localhost | | o.  o           |
2026-03-11 19:09:02.722325 | controller -> localhost | |. = o o          |
2026-03-11 19:09:02.722343 | controller -> localhost | | o B . .         |
2026-03-11 19:09:02.722361 | controller -> localhost | |  * =.. o        |
2026-03-11 19:09:02.722377 | controller -> localhost | | .oOEo+oS+       |
2026-03-11 19:09:02.722393 | controller -> localhost | | ooo==o+=        |
2026-03-11 19:09:02.722409 | controller -> localhost | | o.++.o=.        |
2026-03-11 19:09:02.722426 | controller -> localhost | |. ++.ooo.        |
2026-03-11 19:09:02.722443 | controller -> localhost | | .o. o*o         |
2026-03-11 19:09:02.722459 | controller -> localhost | +----[SHA256]-----+
2026-03-11 19:09:02.722505 | controller -> localhost | ok: Runtime: 0:00:00.198143
2026-03-11 19:09:02.727729 | 
2026-03-11 19:09:02.727789 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-03-11 19:09:02.745866 | controller | ok
2026-03-11 19:09:02.754434 | controller | included: /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-03-11 19:09:02.761346 | 
2026-03-11 19:09:02.761406 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-03-11 19:09:02.774435 | controller | skipping: Conditional result was False
2026-03-11 19:09:02.779114 | 
2026-03-11 19:09:02.779173 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-03-11 19:09:03.243503 | controller | changed
2026-03-11 19:09:03.248119 | 
2026-03-11 19:09:03.248184 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-03-11 19:09:03.519240 | controller | ok
2026-03-11 19:09:03.524079 | 
2026-03-11 19:09:03.524144 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-03-11 19:09:04.766956 | controller | changed
2026-03-11 19:09:04.771932 | 
2026-03-11 19:09:04.771994 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-03-11 19:09:05.993444 | controller | changed
2026-03-11 19:09:05.997789 | 
2026-03-11 19:09:05.997850 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-03-11 19:09:06.011228 | controller | skipping: Conditional result was False
2026-03-11 19:09:06.017382 | 
2026-03-11 19:09:06.017780 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-03-11 19:09:06.298604 | controller -> localhost | changed
2026-03-11 19:09:06.308085 | 
2026-03-11 19:09:06.308154 | TASK [add-build-sshkey : Add back temp key]
2026-03-11 19:09:06.524780 | controller -> localhost | Identity added: /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/035b126cee4e4e759d8cbe4da0f20dc5_id_rsa (zuul-build-sshkey)
2026-03-11 19:09:06.524948 | controller -> localhost | ok: Runtime: 0:00:00.006251
2026-03-11 19:09:06.530208 | 
2026-03-11 19:09:06.530284 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-03-11 19:09:06.903634 | controller | ok
2026-03-11 19:09:06.907784 | 
2026-03-11 19:09:06.907848 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-03-11 19:09:06.933202 | controller | skipping: Conditional result was False
2026-03-11 19:09:06.941419 | 
2026-03-11 19:09:06.941481 | TASK [include_role : validate-host]
2026-03-11 19:09:06.959786 | controller | ok
2026-03-11 19:09:06.977512 | 
2026-03-11 19:09:06.977590 | TASK [validate-host : Define zuul_info_dir fact]
2026-03-11 19:09:07.005721 | controller | ok
2026-03-11 19:09:07.010150 | 
2026-03-11 19:09:07.010211 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-03-11 19:09:07.185614 | controller -> localhost | ok
2026-03-11 19:09:07.190947 | 
2026-03-11 19:09:07.191007 | TASK [validate-host : Collect information about the host]
2026-03-11 19:09:07.914005 | controller | ok
2026-03-11 19:09:07.921106 | 
2026-03-11 19:09:07.921165 | TASK [validate-host : Sanitize hostname]
2026-03-11 19:09:07.960086 | controller | ok
2026-03-11 19:09:07.964642 | 
2026-03-11 19:09:07.964706 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-03-11 19:09:08.328656 | controller -> localhost | changed
2026-03-11 19:09:08.334191 | 
2026-03-11 19:09:08.334258 | TASK [validate-host : Collect information about zuul worker]
2026-03-11 19:09:08.747646 | controller | ok
2026-03-11 19:09:08.751841 | 
2026-03-11 19:09:08.751910 | TASK [validate-host : Write out all zuul information for each host]
2026-03-11 19:09:09.100623 | controller -> localhost | changed
2026-03-11 19:09:09.108834 | 
2026-03-11 19:09:09.108896 | TASK [include_role : prepare-workspace-openshift]
2026-03-11 19:09:09.122320 | controller | skipping: Conditional result was False
2026-03-11 19:09:09.127327 | 
2026-03-11 19:09:09.127387 | TASK [include_role : remove-zuul-sshkey]
2026-03-11 19:09:09.139833 | controller | skipping: Conditional result was False
2026-03-11 19:09:09.144315 | 
2026-03-11 19:09:09.144378 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-03-11 19:09:09.427038 | controller | ok: "logs"
2026-03-11 19:09:09.427259 | controller | ok: All items complete
2026-03-11 19:09:09.427307 | 
2026-03-11 19:09:09.666194 | controller | ok: "artifacts"
2026-03-11 19:09:09.907500 | controller | ok: "docs"
2026-03-11 19:09:09.914908 | 
2026-03-11 19:09:09.915101 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-03-11 19:09:10.198401 | controller | changed: "logs"
2026-03-11 19:09:10.440310 | controller | changed: "artifacts"
2026-03-11 19:09:10.678527 | controller | changed: "docs"
2026-03-11 19:09:10.702903 | 
2026-03-11 19:09:10.702997 | PLAY RECAP
2026-03-11 19:09:10.703045 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-11 19:09:10.703073 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-11 19:09:10.703091 | 
2026-03-11 19:09:10.821636 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-11 19:09:10.822536 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-11 19:09:11.328179 | 
2026-03-11 19:09:11.328302 | PLAY [all]
2026-03-11 19:09:11.346554 | 
2026-03-11 19:09:11.346634 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-11 19:09:11.406807 | controller | ok
2026-03-11 19:09:11.411615 | 
2026-03-11 19:09:11.411689 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-11 19:09:11.816356 | controller | changed
2026-03-11 19:09:11.821330 | 
2026-03-11 19:09:11.821395 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-11 19:09:13.145691 | controller | changed
2026-03-11 19:09:13.155323 | 
2026-03-11 19:09:13.155391 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-03-11 19:09:13.591374 | controller | changed:
2026-03-11 19:09:13.591542 | controller | {
2026-03-11 19:09:13.591584 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-03-11 19:09:13.591615 | controller | }
2026-03-11 19:09:13.909259 | controller | changed:
2026-03-11 19:09:13.909548 | controller | {
2026-03-11 19:09:13.909601 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-03-11 19:09:13.909626 | controller | }
2026-03-11 19:09:14.219895 | controller | changed:
2026-03-11 19:09:14.220086 | controller | {
2026-03-11 19:09:14.220133 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2026-03-11 19:09:14.220158 | controller | }
2026-03-11 19:09:14.550836 | controller | changed:
2026-03-11 19:09:14.550988 | controller | {
2026-03-11 19:09:14.551017 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-03-11 19:09:14.551048 | controller | }
2026-03-11 19:09:14.863087 | controller | changed:
2026-03-11 19:09:14.863279 | controller | {
2026-03-11 19:09:14.863316 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-03-11 19:09:14.863340 | controller | }
2026-03-11 19:09:15.171067 | controller | changed:
2026-03-11 19:09:15.171237 | controller | {
2026-03-11 19:09:15.171315 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-03-11 19:09:15.171346 | controller | }
2026-03-11 19:09:15.481663 | controller | changed:
2026-03-11 19:09:15.481756 | controller | {
2026-03-11 19:09:15.481783 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2026-03-11 19:09:15.481805 | controller | }
2026-03-11 19:09:15.794056 | controller | changed:
2026-03-11 19:09:15.794187 | controller | {
2026-03-11 19:09:15.794216 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2026-03-11 19:09:15.794238 | controller | }
2026-03-11 19:09:16.100450 | controller | changed:
2026-03-11 19:09:16.100631 | controller | {
2026-03-11 19:09:16.100660 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-03-11 19:09:16.100681 | controller | }
2026-03-11 19:09:16.399022 | controller | changed:
2026-03-11 19:09:16.399118 | controller | {
2026-03-11 19:09:16.399145 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-03-11 19:09:16.399166 | controller | }
2026-03-11 19:09:16.705553 | controller | changed:
2026-03-11 19:09:16.705735 | controller | {
2026-03-11 19:09:16.705762 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-03-11 19:09:16.705784 | controller | }
2026-03-11 19:09:17.007371 | controller | changed:
2026-03-11 19:09:17.007520 | controller | {
2026-03-11 19:09:17.007547 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-03-11 19:09:17.007581 | controller | }
2026-03-11 19:09:17.307356 | controller | changed:
2026-03-11 19:09:17.307504 | controller | {
2026-03-11 19:09:17.307539 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-03-11 19:09:17.307572 | controller | }
2026-03-11 19:09:17.604468 | controller | changed:
2026-03-11 19:09:17.604537 | controller | {
2026-03-11 19:09:17.604572 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-03-11 19:09:17.604593 | controller | }
2026-03-11 19:09:17.909623 | controller | changed:
2026-03-11 19:09:17.909675 | controller | {
2026-03-11 19:09:17.909699 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-03-11 19:09:17.909717 | controller | }
2026-03-11 19:09:18.209326 | controller | changed:
2026-03-11 19:09:18.209413 | controller | {
2026-03-11 19:09:18.209438 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-03-11 19:09:18.209457 | controller | }
2026-03-11 19:09:18.500432 | controller | changed:
2026-03-11 19:09:18.500527 | controller | {
2026-03-11 19:09:18.500552 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2026-03-11 19:09:18.500587 | controller | }
2026-03-11 19:09:18.795676 | controller | changed:
2026-03-11 19:09:18.795782 | controller | {
2026-03-11 19:09:18.795808 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2026-03-11 19:09:18.795836 | controller | }
2026-03-11 19:09:19.078441 | controller | changed:
2026-03-11 19:09:19.078544 | controller | {
2026-03-11 19:09:19.078580 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-03-11 19:09:19.078601 | controller | }
2026-03-11 19:09:19.394204 | controller | changed:
2026-03-11 19:09:19.394339 | controller | {
2026-03-11 19:09:19.394366 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-03-11 19:09:19.394385 | controller | }
2026-03-11 19:09:19.698472 | controller | changed:
2026-03-11 19:09:19.698598 | controller | {
2026-03-11 19:09:19.698630 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-03-11 19:09:19.698651 | controller | }
2026-03-11 19:09:19.993976 | controller | changed:
2026-03-11 19:09:19.994025 | controller | {
2026-03-11 19:09:19.994048 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-03-11 19:09:19.994065 | controller | }
2026-03-11 19:09:20.289657 | controller | changed:
2026-03-11 19:09:20.289758 | controller | {
2026-03-11 19:09:20.289783 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2026-03-11 19:09:20.289803 | controller | }
2026-03-11 19:09:20.591777 | controller | changed:
2026-03-11 19:09:20.591872 | controller | {
2026-03-11 19:09:20.591898 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-03-11 19:09:20.591917 | controller | }
2026-03-11 19:09:20.883604 | controller | changed:
2026-03-11 19:09:20.883660 | controller | {
2026-03-11 19:09:20.883683 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-03-11 19:09:20.883701 | controller | }
2026-03-11 19:09:21.199209 | controller | changed:
2026-03-11 19:09:21.199307 | controller | {
2026-03-11 19:09:21.199337 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-03-11 19:09:21.199357 | controller | }
2026-03-11 19:09:21.215915 | 
2026-03-11 19:09:21.216006 | TASK [Set timezone to UTC]
2026-03-11 19:09:21.772141 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-03-11 19:09:21.780525 | 
2026-03-11 19:09:21.780617 | TASK [Create nodepool directory]
2026-03-11 19:09:22.096443 | controller | changed
2026-03-11 19:09:22.101484 | 
2026-03-11 19:09:22.101543 | TASK [Create nodepool sub_nodes file]
2026-03-11 19:09:23.114430 | controller | changed
2026-03-11 19:09:23.118838 | 
2026-03-11 19:09:23.118898 | TASK [Create nodepool sub_nodes_private file]
2026-03-11 19:09:24.081914 | controller | changed
2026-03-11 19:09:24.086227 | 
2026-03-11 19:09:24.086318 | LOOP [Populate nodepool sub_nodes file]
2026-03-11 19:09:24.114862 | 
2026-03-11 19:09:24.114974 | LOOP [Populate nodepool sub_nodes_private file]
2026-03-11 19:09:24.143109 | 
2026-03-11 19:09:24.143225 | TASK [Create nodepool primary file]
2026-03-11 19:09:24.167064 | controller | skipping: Conditional result was False
2026-03-11 19:09:24.172029 | 
2026-03-11 19:09:24.172096 | TASK [Create nodepool node_private for this node]
2026-03-11 19:09:25.266341 | controller | changed
2026-03-11 19:09:25.271734 | 
2026-03-11 19:09:25.271797 | LOOP [Copy ssh keys to nodepool directory]
2026-03-11 19:09:25.656653 | controller | ok: Item: id_rsa Runtime: 0:00:00.006268
2026-03-11 19:09:25.656853 | 
2026-03-11 19:09:25.909515 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006464
2026-03-11 19:09:25.919997 | 
2026-03-11 19:09:25.920080 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-03-11 19:09:26.983134 | controller | changed
2026-03-11 19:09:26.987620 | 
2026-03-11 19:09:26.987680 | TASK [Validate sudoers config after edits]
2026-03-11 19:09:27.283184 | controller | /etc/sudoers: parsed OK
2026-03-11 19:09:27.283237 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-03-11 19:09:27.283245 | controller | /etc/sudoers.d/zuul: parsed OK
2026-03-11 19:09:27.283251 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-03-11 19:09:27.510782 | controller | ok: Runtime: 0:00:00.005446
2026-03-11 19:09:27.515415 | 
2026-03-11 19:09:27.515474 | TASK [Show the environment passed in to job shell scripts]
2026-03-11 19:09:27.792594 | controller | SHELL=/bin/bash
2026-03-11 19:09:27.792648 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-03-11 19:09:27.792662 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-03-11 19:09:27.792670 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/39/3739/4709c7f0378ced4dce348fbc73c002c8dcd7febf
2026-03-11 19:09:27.792676 | controller | PWD=/home/zuul
2026-03-11 19:09:27.792681 | controller | ZUUL_PIPELINE=github-check
2026-03-11 19:09:27.792686 | controller | LOGNAME=zuul
2026-03-11 19:09:27.792719 | controller | XDG_SESSION_TYPE=tty
2026-03-11 19:09:27.792727 | controller | _=/usr/bin/env
2026-03-11 19:09:27.792733 | controller | MOTD_SHOWN=pam
2026-03-11 19:09:27.792738 | controller | HOME=/home/zuul
2026-03-11 19:09:27.792743 | controller | LANG=en_US.UTF-8
2026-03-11 19:09:27.792757 | controller | SSH_CONNECTION=192.168.25.12 60846 192.168.25.47 22
2026-03-11 19:09:27.792763 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2026-03-11 19:09:27.792771 | controller | ZUUL_CHANGE_IDS=3739,4709c7f0378ced4dce348fbc73c002c8dcd7febf
2026-03-11 19:09:27.792777 | controller | WORKSPACE=/home/zuul/workspace
2026-03-11 19:09:27.792782 | controller | XDG_SESSION_CLASS=user
2026-03-11 19:09:27.792788 | controller | SELINUX_ROLE_REQUESTED=
2026-03-11 19:09:27.792793 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-03-11 19:09:27.792799 | controller | USER=zuul
2026-03-11 19:09:27.792804 | controller | ZUUL_VOTING=True
2026-03-11 19:09:27.792809 | controller | BUILD_TIMEOUT=5400000
2026-03-11 19:09:27.792814 | controller | SELINUX_USE_CURRENT_RANGE=
2026-03-11 19:09:27.792819 | controller | SHLVL=1
2026-03-11 19:09:27.792825 | controller | ZUUL_PATCHSET=4709c7f0378ced4dce348fbc73c002c8dcd7febf
2026-03-11 19:09:27.792830 | controller | XDG_SESSION_ID=1
2026-03-11 19:09:27.792835 | controller | ZUUL_BRANCH=main
2026-03-11 19:09:27.792841 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-03-11 19:09:27.792846 | controller | SSH_CLIENT=192.168.25.12 60846 22
2026-03-11 19:09:27.792851 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-03-11 19:09:27.792857 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-03-11 19:09:27.792862 | controller | which_declare=declare -f
2026-03-11 19:09:27.792868 | controller | PATH=/home/zuul/.crc/bin/oc:/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2026-03-11 19:09:27.792873 | controller | SELINUX_LEVEL_REQUESTED=
2026-03-11 19:09:27.792878 | controller | ZUUL_CHANGE=3739
2026-03-11 19:09:27.792884 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-03-11 19:09:27.792889 | controller | ZUUL_UUID=035b126cee4e4e759d8cbe4da0f20dc5
2026-03-11 19:09:27.792894 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-03-11 19:09:27.792900 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-03-11 19:09:27.792905 | controller | }
2026-03-11 19:09:28.040357 | controller | ok: Runtime: 0:00:00.006247
2026-03-11 19:09:28.045079 | 
2026-03-11 19:09:28.045138 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-03-11 19:09:28.058317 | controller | skipping: Conditional result was False
2026-03-11 19:09:28.063468 | 
2026-03-11 19:09:28.063532 | TASK [Symlink /home/zuul-worker/workspace]
2026-03-11 19:09:28.607212 | controller | skipping: Conditional result was False
2026-03-11 19:09:28.612371 | 
2026-03-11 19:09:28.612431 | TASK [Ensure legacy workspace directory]
2026-03-11 19:09:28.894620 | controller | changed
2026-03-11 19:09:28.912398 | 
2026-03-11 19:09:28.912448 | PLAY RECAP
2026-03-11 19:09:28.912490 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-11 19:09:28.912513 | 
2026-03-11 19:09:28.977471 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-11 19:09:28.978197 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-11 19:09:29.475924 | 
2026-03-11 19:09:29.476022 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-03-11 19:09:29.496807 | 
2026-03-11 19:09:29.496880 | TASK [Create zuul-output directory]
2026-03-11 19:09:29.869991 | controller | changed
2026-03-11 19:09:29.874704 | 
2026-03-11 19:09:29.874773 | TASK [Slurp Zuul inventory test]
2026-03-11 19:09:30.120952 | controller -> localhost | ok
2026-03-11 19:09:30.126635 | 
2026-03-11 19:09:30.126694 | TASK [Save zuul inventory]
2026-03-11 19:09:31.364898 | controller | changed
2026-03-11 19:09:31.370020 | 
2026-03-11 19:09:31.370079 | TASK [Save zuul vars without the change_message]
2026-03-11 19:09:32.436836 | controller | changed
2026-03-11 19:09:32.456809 | 
2026-03-11 19:09:32.456877 | PLAY RECAP
2026-03-11 19:09:32.456926 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-11 19:09:32.456948 | 
2026-03-11 19:09:32.560381 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-11 19:09:32.561062 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-11 19:09:33.058802 | 
2026-03-11 19:09:33.058897 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-03-11 19:09:33.077338 | 
2026-03-11 19:09:33.077403 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-03-11 19:09:33.095550 | controller | ok
2026-03-11 19:09:33.110490 | 
2026-03-11 19:09:33.110573 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-11 19:09:33.134192 | controller | skipping: Conditional result was False
2026-03-11 19:09:33.139376 | 
2026-03-11 19:09:33.139441 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-11 19:09:33.532992 | controller | ok
2026-03-11 19:09:33.538144 | 
2026-03-11 19:09:33.538207 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-11 19:09:34.483678 | controller | ok
2026-03-11 19:09:34.492074 | 
2026-03-11 19:09:34.492133 | TASK [Prepare workspace]
2026-03-11 19:09:34.510238 | controller | ok
2026-03-11 19:09:34.525313 | 
2026-03-11 19:09:34.525372 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-03-11 19:09:34.878335 | controller | ok
2026-03-11 19:09:34.883701 | 
2026-03-11 19:09:34.883762 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-03-11 19:09:37.236017 | controller | Output suppressed because no_log was given
2026-03-11 19:09:37.244317 | 
2026-03-11 19:09:37.244379 | LOOP [Create zuul-output directory]
2026-03-11 19:09:37.505134 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-03-11 19:09:37.740723 | controller | ok: "/home/zuul/zuul-output/logs"
2026-03-11 19:09:37.751827 | 
2026-03-11 19:09:37.751904 | TASK [Install required packages]
2026-03-11 19:09:56.917422 | controller | ok: Nothing to do
2026-03-11 19:09:56.921910 | 
2026-03-11 19:09:56.921963 | TASK [Install venv]
2026-03-11 19:10:58.057664 | controller | changed
2026-03-11 19:10:58.096871 | 
2026-03-11 19:10:58.096946 | PLAY RECAP
2026-03-11 19:10:58.096984 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-03-11 19:10:58.097005 | 
2026-03-11 19:10:58.154258 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-11 19:10:58.155044 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-11 19:10:58.626042 | 
2026-03-11 19:10:58.626129 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-03-11 19:10:58.644788 | 
2026-03-11 19:10:58.644853 | TASK [Gather required facts]
2026-03-11 19:10:59.181040 | controller | ok
2026-03-11 19:10:59.186263 | 
2026-03-11 19:10:59.186356 | TASK [Load environment var if instructed to]
2026-03-11 19:10:59.210070 | controller | skipping: Conditional result was False
2026-03-11 19:10:59.215002 | 
2026-03-11 19:10:59.215064 | TASK [Ensure group_vars dir exists]
2026-03-11 19:10:59.589060 | controller | ok
2026-03-11 19:10:59.593591 | 
2026-03-11 19:10:59.593653 | TASK [Print related variables]
2026-03-11 19:10:59.621776 | controller | ok:
2026-03-11 19:10:59.621882 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-03-11 19:10:59.621910 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer
2026-03-11 19:10:59.626121 | 
2026-03-11 19:10:59.626183 | TASK [Run molecule]
2026-03-11 19:11:00.641270 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-03-11 19:11:00.974484 | controller | INFO     Running bm_redfish > prepare
2026-03-11 19:11:01.633830 | controller |
2026-03-11 19:11:01.633913 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-03-11 19:11:01.634044 | controller |
2026-03-11 19:11:01.634056 | controller | TASK [Create mock server directory] ********************************************
2026-03-11 19:11:01.634067 | controller | Wednesday 11 March 2026  19:11:01 +0000 (0:00:00.024)       0:00:00.024 *******
2026-03-11 19:11:01.986583 | controller | changed: [instance]
2026-03-11 19:11:01.986642 | controller |
2026-03-11 19:11:01.986729 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-03-11 19:11:01.986831 | controller | Wednesday 11 March 2026  19:11:01 +0000 (0:00:00.353)       0:00:00.378 *******
2026-03-11 19:11:02.405386 | controller | changed: [instance]
2026-03-11 19:11:02.405434 | controller |
2026-03-11 19:11:02.405518 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-03-11 19:11:02.405608 | controller | Wednesday 11 March 2026  19:11:02 +0000 (0:00:00.418)       0:00:00.797 *******
2026-03-11 19:11:02.926996 | controller | changed: [instance]
2026-03-11 19:11:02.927118 | controller |
2026-03-11 19:11:02.927294 | controller | TASK [Start mock iDRAC server] *************************************************
2026-03-11 19:11:02.927467 | controller | Wednesday 11 March 2026  19:11:02 +0000 (0:00:00.521)       0:00:01.318 *******
2026-03-11 19:11:03.117282 | controller | changed: [instance]
2026-03-11 19:11:03.117325 | controller |
2026-03-11 19:11:03.118138 | controller | TASK [Record mock server PID] **************************************************
2026-03-11 19:11:03.118209 | controller | Wednesday 11 March 2026  19:11:03 +0000 (0:00:00.190)       0:00:01.509 *******
2026-03-11 19:11:03.326576 | controller | ok: [instance]
2026-03-11 19:11:03.326664 | controller |
2026-03-11 19:11:03.326819 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-03-11 19:11:03.326930 | controller | Wednesday 11 March 2026  19:11:03 +0000 (0:00:00.209)       0:00:01.718 *******
2026-03-11 19:11:03.748809 | controller | ok: [instance]
2026-03-11 19:11:03.748861 | controller |
2026-03-11 19:11:03.748924 | controller | PLAY RECAP *********************************************************************
2026-03-11 19:11:03.749017 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-03-11 19:11:03.749097 | controller |
2026-03-11 19:11:03.749184 | controller | Wednesday 11 March 2026  19:11:03 +0000 (0:00:00.422)       0:00:02.141 *******
2026-03-11 19:11:03.749257 | controller | ===============================================================================
2026-03-11 19:11:03.749345 | controller | Copy mock iDRAC server script ------------------------------------------- 0.52s
2026-03-11 19:11:03.749429 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.42s
2026-03-11 19:11:03.749515 | controller | Generate self-signed TLS certificate ------------------------------------ 0.42s
2026-03-11 19:11:03.749597 | controller | Create mock server directory -------------------------------------------- 0.35s
2026-03-11 19:11:03.749701 | controller | Record mock server PID -------------------------------------------------- 0.21s
2026-03-11 19:11:03.749805 | controller | Start mock iDRAC server ------------------------------------------------- 0.19s
2026-03-11 19:11:03.820987 | controller | INFO     Running bm_redfish > converge
2026-03-11 19:11:04.229082 | controller |
2026-03-11 19:11:04.229376 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-03-11 19:11:04.229455 | controller |
2026-03-11 19:11:04.229471 | controller | TASK [Test bm_power_off] *******************************************************
2026-03-11 19:11:04.229654 | controller | Wednesday 11 March 2026  19:11:04 +0000 (0:00:00.045)       0:00:00.045 *******
2026-03-11 19:11:04.252892 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_power_off.yml for instance
2026-03-11 19:11:04.253028 | controller |
2026-03-11 19:11:04.253259 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-11 19:11:04.675299 | controller | Wednesday 11 March 2026  19:11:04 +0000 (0:00:00.024)       0:00:00.070 *******
2026-03-11 19:11:04.675385 | controller | ok: [instance]
2026-03-11 19:11:04.675417 | controller |
2026-03-11 19:11:04.675574 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-11 19:11:04.675739 | controller | Wednesday 11 March 2026  19:11:04 +0000 (0:00:00.422)       0:00:00.492 *******
2026-03-11 19:11:04.706927 | controller |
2026-03-11 19:11:04.707004 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:04.707086 | controller | Wednesday 11 March 2026  19:11:04 +0000 (0:00:00.032)       0:00:00.524 *******
2026-03-11 19:11:05.008807 | controller | ok: [instance]
2026-03-11 19:11:05.008884 | controller |
2026-03-11 19:11:05.008896 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-11 19:11:05.009004 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.301)       0:00:00.826 *******
2026-03-11 19:11:05.030108 | controller | skipping: [instance]
2026-03-11 19:11:05.030173 | controller |
2026-03-11 19:11:05.030266 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-11 19:11:05.030364 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.021)       0:00:00.848 *******
2026-03-11 19:11:05.054135 | controller | skipping: [instance]
2026-03-11 19:11:05.054251 | controller |
2026-03-11 19:11:05.054383 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-03-11 19:11:05.054514 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.023)       0:00:00.872 *******
2026-03-11 19:11:05.388841 | controller | ok: [instance]
2026-03-11 19:11:05.412762 | controller |
2026-03-11 19:11:05.412782 | controller | TASK [Assert host is still Off] ************************************************
2026-03-11 19:11:05.412790 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.333)       0:00:01.205 *******
2026-03-11 19:11:05.412799 | controller | ok: [instance] => {
2026-03-11 19:11:05.413291 | controller |     "changed": false,
2026-03-11 19:11:05.413361 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:05.713872 | controller | }
2026-03-11 19:11:05.713952 | controller |
2026-03-11 19:11:05.713967 | controller | TASK [Reset mock to power On] **************************************************
2026-03-11 19:11:05.713979 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.024)       0:00:01.230 *******
2026-03-11 19:11:05.714001 | controller | ok: [instance]
2026-03-11 19:11:05.740433 | controller |
2026-03-11 19:11:05.740473 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-11 19:11:05.740483 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.300)       0:00:01.531 *******
2026-03-11 19:11:05.740495 | controller |
2026-03-11 19:11:06.024606 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:06.024676 | controller | Wednesday 11 March 2026  19:11:05 +0000 (0:00:00.026)       0:00:01.558 *******
2026-03-11 19:11:06.024697 | controller | ok: [instance]
2026-03-11 19:11:06.323411 | controller |
2026-03-11 19:11:06.323452 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-11 19:11:06.323466 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.283)       0:00:01.841 *******
2026-03-11 19:11:06.323482 | controller | ok: [instance]
2026-03-11 19:11:06.613707 | controller |
2026-03-11 19:11:06.613729 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-11 19:11:06.613736 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.298)       0:00:02.140 *******
2026-03-11 19:11:06.613744 | controller | ok: [instance]
2026-03-11 19:11:06.908112 | controller |
2026-03-11 19:11:06.908169 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-03-11 19:11:06.908178 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.290)       0:00:02.431 *******
2026-03-11 19:11:06.908192 | controller | ok: [instance]
2026-03-11 19:11:06.932100 | controller |
2026-03-11 19:11:06.932132 | controller | TASK [Assert host is now Off] **************************************************
2026-03-11 19:11:06.932141 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.294)       0:00:02.725 *******
2026-03-11 19:11:06.932151 | controller | ok: [instance] => {
2026-03-11 19:11:06.957448 | controller |     "changed": false,
2026-03-11 19:11:06.957469 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:06.957492 | controller | }
2026-03-11 19:11:06.957500 | controller |
2026-03-11 19:11:06.957507 | controller | TASK [Test bm_power_on] ********************************************************
2026-03-11 19:11:06.957513 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.023)       0:00:02.749 *******
2026-03-11 19:11:06.957523 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_power_on.yml for instance
2026-03-11 19:11:07.262509 | controller |
2026-03-11 19:11:07.262565 | controller | TASK [Reset mock to power On] **************************************************
2026-03-11 19:11:07.262574 | controller | Wednesday 11 March 2026  19:11:06 +0000 (0:00:00.025)       0:00:02.775 *******
2026-03-11 19:11:07.262587 | controller | ok: [instance]
2026-03-11 19:11:07.293459 | controller |
2026-03-11 19:11:07.293506 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-11 19:11:07.293516 | controller | Wednesday 11 March 2026  19:11:07 +0000 (0:00:00.304)       0:00:03.079 *******
2026-03-11 19:11:07.293530 | controller |
2026-03-11 19:11:07.596027 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:07.596056 | controller | Wednesday 11 March 2026  19:11:07 +0000 (0:00:00.031)       0:00:03.110 *******
2026-03-11 19:11:07.596067 | controller | ok: [instance]
2026-03-11 19:11:07.615318 | controller |
2026-03-11 19:11:07.615333 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-11 19:11:07.615339 | controller | Wednesday 11 March 2026  19:11:07 +0000 (0:00:00.302)       0:00:03.413 *******
2026-03-11 19:11:07.615347 | controller | skipping: [instance]
2026-03-11 19:11:07.925801 | controller |
2026-03-11 19:11:07.925863 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-11 19:11:07.925873 | controller | Wednesday 11 March 2026  19:11:07 +0000 (0:00:00.019)       0:00:03.433 *******
2026-03-11 19:11:07.925887 | controller | ok: [instance]
2026-03-11 19:11:07.925894 | controller |
2026-03-11 19:11:07.925904 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-03-11 19:11:08.233890 | controller | Wednesday 11 March 2026  19:11:07 +0000 (0:00:00.310)       0:00:03.743 *******
2026-03-11 19:11:08.233965 | controller | ok: [instance]
2026-03-11 19:11:08.258498 | controller |
2026-03-11 19:11:08.258551 | controller | TASK [Assert host is still On] *************************************************
2026-03-11 19:11:08.258561 | controller | Wednesday 11 March 2026  19:11:08 +0000 (0:00:00.307)       0:00:04.051 *******
2026-03-11 19:11:08.258573 | controller | ok: [instance] => {
2026-03-11 19:11:08.555823 | controller |     "changed": false,
2026-03-11 19:11:08.555887 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:08.555898 | controller | }
2026-03-11 19:11:08.555913 | controller |
2026-03-11 19:11:08.555920 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-11 19:11:08.555928 | controller | Wednesday 11 March 2026  19:11:08 +0000 (0:00:00.024)       0:00:04.075 *******
2026-03-11 19:11:08.555942 | controller | ok: [instance]
2026-03-11 19:11:08.556054 | controller |
2026-03-11 19:11:08.556124 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-11 19:11:08.584091 | controller | Wednesday 11 March 2026  19:11:08 +0000 (0:00:00.297)       0:00:04.373 *******
2026-03-11 19:11:08.584127 | controller |
2026-03-11 19:11:08.871197 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:08.871254 | controller | Wednesday 11 March 2026  19:11:08 +0000 (0:00:00.028)       0:00:04.401 *******
2026-03-11 19:11:08.871269 | controller | ok: [instance]
2026-03-11 19:11:09.178005 | controller |
2026-03-11 19:11:09.178073 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-11 19:11:09.178082 | controller | Wednesday 11 March 2026  19:11:08 +0000 (0:00:00.286)       0:00:04.687 *******
2026-03-11 19:11:09.178096 | controller | ok: [instance]
2026-03-11 19:11:09.471756 | controller |
2026-03-11 19:11:09.471815 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-11 19:11:09.471824 | controller | Wednesday 11 March 2026  19:11:09 +0000 (0:00:00.304)       0:00:04.992 *******
2026-03-11 19:11:09.471838 | controller | ok: [instance]
2026-03-11 19:11:09.471880 | controller |
2026-03-11 19:11:09.471909 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-03-11 19:11:09.472123 | controller | Wednesday 11 March 2026  19:11:09 +0000 (0:00:00.296)       0:00:05.289 *******
2026-03-11 19:11:09.780396 | controller | ok: [instance]
2026-03-11 19:11:09.806494 | controller |
2026-03-11 19:11:09.806527 | controller | TASK [Assert host is now On] ***************************************************
2026-03-11 19:11:09.806537 | controller | Wednesday 11 March 2026  19:11:09 +0000 (0:00:00.308)       0:00:05.597 *******
2026-03-11 19:11:09.806549 | controller | ok: [instance] => {
2026-03-11 19:11:09.834252 | controller |     "changed": false,
2026-03-11 19:11:09.834275 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:09.834284 | controller | }
2026-03-11 19:11:09.834291 | controller |
2026-03-11 19:11:09.834298 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-03-11 19:11:09.834304 | controller | Wednesday 11 March 2026  19:11:09 +0000 (0:00:00.026)       0:00:05.623 *******
2026-03-11 19:11:09.834315 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_check_usb_boot.yml for instance
2026-03-11 19:11:10.137806 | controller |
2026-03-11 19:11:10.137860 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-03-11 19:11:10.137872 | controller | Wednesday 11 March 2026  19:11:09 +0000 (0:00:00.028)       0:00:05.651 *******
2026-03-11 19:11:10.137889 | controller | ok: [instance]
2026-03-11 19:11:10.165057 | controller |
2026-03-11 19:11:10.165103 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-03-11 19:11:10.165114 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.303)       0:00:05.955 *******
2026-03-11 19:11:10.165127 | controller |
2026-03-11 19:11:10.451760 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-11 19:11:10.451793 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.027)       0:00:05.982 *******
2026-03-11 19:11:10.451805 | controller | ok: [instance]
2026-03-11 19:11:10.451837 | controller |
2026-03-11 19:11:10.452231 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-11 19:11:10.488800 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.286)       0:00:06.269 *******
2026-03-11 19:11:10.488876 | controller | ok: [instance]
2026-03-11 19:11:10.488989 | controller |
2026-03-11 19:11:10.489021 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-11 19:11:10.521880 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.037)       0:00:06.306 *******
2026-03-11 19:11:10.521946 | controller | skipping: [instance]
2026-03-11 19:11:10.522003 | controller |
2026-03-11 19:11:10.522019 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-03-11 19:11:10.557538 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.033)       0:00:06.339 *******
2026-03-11 19:11:10.557571 | controller | ok: [instance] => {
2026-03-11 19:11:10.850172 | controller |     "changed": false,
2026-03-11 19:11:10.850199 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:10.850208 | controller | }
2026-03-11 19:11:10.850214 | controller |
2026-03-11 19:11:10.850220 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-11 19:11:10.850226 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.035)       0:00:06.374 *******
2026-03-11 19:11:10.850234 | controller | ok: [instance]
2026-03-11 19:11:10.879251 | controller |
2026-03-11 19:11:10.879280 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-03-11 19:11:10.879292 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.293)       0:00:06.667 *******
2026-03-11 19:11:10.879307 | controller |
2026-03-11 19:11:11.198773 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-11 19:11:11.198834 | controller | Wednesday 11 March 2026  19:11:10 +0000 (0:00:00.028)       0:00:06.696 *******
2026-03-11 19:11:11.198858 | controller | ok: [instance]
2026-03-11 19:11:11.199299 | controller |
2026-03-11 19:11:11.235430 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-11 19:11:11.235449 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.319)       0:00:07.016 *******
2026-03-11 19:11:11.235469 | controller | ok: [instance]
2026-03-11 19:11:11.264554 | controller |
2026-03-11 19:11:11.264573 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-11 19:11:11.264580 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.036)       0:00:07.052 *******
2026-03-11 19:11:11.264588 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-11 19:11:11.269583 | controller |
2026-03-11 19:11:11.293792 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-03-11 19:11:11.293843 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.034)       0:00:07.087 *******
2026-03-11 19:11:11.293860 | controller | ok: [instance] => {
2026-03-11 19:11:11.324236 | controller |     "changed": false,
2026-03-11 19:11:11.324265 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:11.324273 | controller | }
2026-03-11 19:11:11.324279 | controller |
2026-03-11 19:11:11.324285 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-03-11 19:11:11.324290 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.023)       0:00:07.110 *******
2026-03-11 19:11:11.324300 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_ensure_usb_boot.yml for instance
2026-03-11 19:11:11.608164 | controller |
2026-03-11 19:11:11.608182 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-03-11 19:11:11.608189 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.031)       0:00:07.141 *******
2026-03-11 19:11:11.608198 | controller | ok: [instance]
2026-03-11 19:11:11.641593 | controller |
2026-03-11 19:11:11.641611 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-03-11 19:11:11.641618 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.283)       0:00:07.425 *******
2026-03-11 19:11:11.641641 | controller |
2026-03-11 19:11:11.663621 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-11 19:11:11.663656 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.034)       0:00:07.459 *******
2026-03-11 19:11:11.663667 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-11 19:11:11.952437 | controller |
2026-03-11 19:11:11.952459 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-11 19:11:11.952466 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.021)       0:00:07.481 *******
2026-03-11 19:11:11.952474 | controller | ok: [instance]
2026-03-11 19:11:11.987842 | controller |
2026-03-11 19:11:11.987898 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-11 19:11:11.987908 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.288)       0:00:07.770 *******
2026-03-11 19:11:11.987923 | controller | ok: [instance]
2026-03-11 19:11:12.021810 | controller |
2026-03-11 19:11:12.021856 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-11 19:11:12.021868 | controller | Wednesday 11 March 2026  19:11:11 +0000 (0:00:00.035)       0:00:07.805 *******
2026-03-11 19:11:12.021885 | controller | skipping: [instance]
2026-03-11 19:11:12.022791 | controller |
2026-03-11 19:11:12.022822 | controller | TASK [Query mock state] ********************************************************
2026-03-11 19:11:12.317686 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.034)       0:00:07.839 *******
2026-03-11 19:11:12.317718 | controller | ok: [instance]
2026-03-11 19:11:12.343189 | controller |
2026-03-11 19:11:12.343209 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-03-11 19:11:12.343217 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.295)       0:00:08.135 *******
2026-03-11 19:11:12.343227 | controller | ok: [instance] => {
2026-03-11 19:11:12.343391 | controller |     "changed": false,
2026-03-11 19:11:12.343540 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:12.343723 | controller | }
2026-03-11 19:11:12.343882 | controller |
2026-03-11 19:11:12.344028 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-03-11 19:11:12.344171 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.026)       0:00:08.161 *******
2026-03-11 19:11:12.635774 | controller | ok: [instance]
2026-03-11 19:11:12.635848 | controller |
2026-03-11 19:11:12.635859 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-03-11 19:11:12.636030 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.291)       0:00:08.452 *******
2026-03-11 19:11:12.670059 | controller |
2026-03-11 19:11:12.696314 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-11 19:11:12.696336 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.033)       0:00:08.486 *******
2026-03-11 19:11:12.696350 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-11 19:11:13.009300 | controller |
2026-03-11 19:11:13.009341 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-11 19:11:13.009358 | controller | Wednesday 11 March 2026  19:11:12 +0000 (0:00:00.027)       0:00:08.513 *******
2026-03-11 19:11:13.009371 | controller | ok: [instance]
2026-03-11 19:11:13.046443 | controller |
2026-03-11 19:11:13.046463 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-11 19:11:13.046472 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.312)       0:00:08.826 *******
2026-03-11 19:11:13.046483 | controller | ok: [instance]
2026-03-11 19:11:13.074957 | controller |
2026-03-11 19:11:13.074980 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-11 19:11:13.074989 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.037)       0:00:08.864 *******
2026-03-11 19:11:13.075001 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-11 19:11:13.080137 | controller |
2026-03-11 19:11:13.117348 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-11 19:11:13.117366 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.033)       0:00:08.897 *******
2026-03-11 19:11:13.117376 | controller | skipping: [instance]
2026-03-11 19:11:13.413587 | controller |
2026-03-11 19:11:13.413610 | controller | TASK [reproducer : Set GenericUsbBoot BIOS attribute] **************************
2026-03-11 19:11:13.413619 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.037)       0:00:08.934 *******
2026-03-11 19:11:13.413659 | controller | ok: [instance]
2026-03-11 19:11:13.708007 | controller |
2026-03-11 19:11:13.708029 | controller | TASK [reproducer : Create BIOS config job to schedule the change] **************
2026-03-11 19:11:13.708037 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.296)       0:00:09.231 *******
2026-03-11 19:11:13.708047 | controller | ok: [instance]
2026-03-11 19:11:13.735143 | controller |
2026-03-11 19:11:13.735164 | controller | TASK [reproducer : Power off before applying BIOS change] **********************
2026-03-11 19:11:13.735173 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.294)       0:00:09.525 *******
2026-03-11 19:11:13.735184 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-11 19:11:14.048408 | controller |
2026-03-11 19:11:14.048443 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:14.048451 | controller | Wednesday 11 March 2026  19:11:13 +0000 (0:00:00.027)       0:00:09.552 *******
2026-03-11 19:11:14.048463 | controller | ok: [instance]
2026-03-11 19:11:14.069178 | controller |
2026-03-11 19:11:14.069196 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-11 19:11:14.069203 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.312)       0:00:09.865 *******
2026-03-11 19:11:14.069212 | controller | skipping: [instance]
2026-03-11 19:11:14.088888 | controller |
2026-03-11 19:11:14.088963 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-11 19:11:14.088978 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.021)       0:00:09.886 *******
2026-03-11 19:11:14.088999 | controller | skipping: [instance]
2026-03-11 19:11:14.116442 | controller |
2026-03-11 19:11:14.116473 | controller | TASK [reproducer : Power on to apply BIOS config job during POST] **************
2026-03-11 19:11:14.116494 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.019)       0:00:09.906 *******
2026-03-11 19:11:14.116507 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_on.yml for instance
2026-03-11 19:11:14.408984 | controller |
2026-03-11 19:11:14.409034 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:14.409042 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.027)       0:00:09.934 *******
2026-03-11 19:11:14.409055 | controller | ok: [instance]
2026-03-11 19:11:14.720953 | controller |
2026-03-11 19:11:14.720989 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-11 19:11:14.720998 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.292)       0:00:10.226 *******
2026-03-11 19:11:14.721009 | controller | ok: [instance]
2026-03-11 19:11:15.011069 | controller |
2026-03-11 19:11:15.011090 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-11 19:11:15.011098 | controller | Wednesday 11 March 2026  19:11:14 +0000 (0:00:00.312)       0:00:10.538 *******
2026-03-11 19:11:15.011107 | controller | ok: [instance]
2026-03-11 19:11:15.040831 | controller |
2026-03-11 19:11:15.040890 | controller | TASK [reproducer : Power off after BIOS change applied] ************************
2026-03-11 19:11:15.040901 | controller | Wednesday 11 March 2026  19:11:15 +0000 (0:00:00.290)       0:00:10.828 *******
2026-03-11 19:11:15.040919 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-11 19:11:15.339823 | controller |
2026-03-11 19:11:15.339867 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-11 19:11:15.339880 | controller | Wednesday 11 March 2026  19:11:15 +0000 (0:00:00.029)       0:00:10.858 *******
2026-03-11 19:11:15.339909 | controller | ok: [instance]
2026-03-11 19:11:15.628820 | controller |
2026-03-11 19:11:15.628869 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-11 19:11:15.628879 | controller | Wednesday 11 March 2026  19:11:15 +0000 (0:00:00.298)       0:00:11.157 *******
2026-03-11 19:11:15.628891 | controller | ok: [instance]
2026-03-11 19:11:15.927651 | controller |
2026-03-11 19:11:15.927684 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-11 19:11:15.927692 | controller | Wednesday 11 March 2026  19:11:15 +0000 (0:00:00.289)       0:00:11.446 *******
2026-03-11 19:11:15.927703 | controller | ok: [instance]
2026-03-11 19:11:16.224204 | controller |
2026-03-11 19:11:16.224226 | controller | TASK [Query mock state after auto-enable] **************************************
2026-03-11 19:11:16.224233 | controller | Wednesday 11 March 2026  19:11:15 +0000 (0:00:00.298)       0:00:11.745 *******
2026-03-11 19:11:16.224242 | controller | ok: [instance]
2026-03-11 19:11:16.253113 | controller |
2026-03-11 19:11:16.253132 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-03-11 19:11:16.253140 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.296)       0:00:12.041 *******
2026-03-11 19:11:16.253150 | controller | ok: [instance] => {
2026-03-11 19:11:16.550513 | controller |     "changed": false,
2026-03-11 19:11:16.550567 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:16.550578 | controller | }
2026-03-11 19:11:16.550586 | controller |
2026-03-11 19:11:16.550593 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-11 19:11:16.550601 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.028)       0:00:12.070 *******
2026-03-11 19:11:16.550615 | controller | ok: [instance]
2026-03-11 19:11:16.582624 | controller |
2026-03-11 19:11:16.582668 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-03-11 19:11:16.582676 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.297)       0:00:12.367 *******
2026-03-11 19:11:16.582686 | controller |
2026-03-11 19:11:16.606868 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-11 19:11:16.606925 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.032)       0:00:12.400 *******
2026-03-11 19:11:16.606948 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-11 19:11:16.606998 | controller |
2026-03-11 19:11:16.607013 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-11 19:11:16.901725 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.024)       0:00:12.424 *******
2026-03-11 19:11:16.901779 | controller | ok: [instance]
2026-03-11 19:11:16.901789 | controller |
2026-03-11 19:11:16.901795 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-11 19:11:16.901803 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.294)       0:00:12.718 *******
2026-03-11 19:11:16.936978 | controller | ok: [instance]
2026-03-11 19:11:16.969493 | controller |
2026-03-11 19:11:16.969542 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-11 19:11:16.969551 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.035)       0:00:12.754 *******
2026-03-11 19:11:16.969564 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-11 19:11:16.974220 | controller |
2026-03-11 19:11:17.006115 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-11 19:11:17.006141 | controller | Wednesday 11 March 2026  19:11:16 +0000 (0:00:00.037)       0:00:12.792 *******
2026-03-11 19:11:17.006152 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443. Set cifmw_bm_agent_enable_usb_boot: true in vars.yaml to allow this playbook to enable it automatically (requires a reboot cycle)."}
2026-03-11 19:11:17.011709 | controller |
2026-03-11 19:11:17.038864 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-03-11 19:11:17.038921 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.037)       0:00:12.829 *******
2026-03-11 19:11:17.038936 | controller | ok: [instance] => {
2026-03-11 19:11:17.069392 | controller |     "changed": false,
2026-03-11 19:11:17.069418 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:17.069427 | controller | }
2026-03-11 19:11:17.069434 | controller |
2026-03-11 19:11:17.069440 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-03-11 19:11:17.069446 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.026)       0:00:12.855 *******
2026-03-11 19:11:17.069456 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_eject_vmedia.yml for instance
2026-03-11 19:11:17.069594 | controller |
2026-03-11 19:11:17.069765 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-11 19:11:17.069914 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.031)       0:00:12.887 *******
2026-03-11 19:11:17.363201 | controller | ok: [instance]
2026-03-11 19:11:17.388410 | controller |
2026-03-11 19:11:17.388433 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-03-11 19:11:17.388441 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.292)       0:00:13.180 *******
2026-03-11 19:11:17.388451 | controller |
2026-03-11 19:11:17.682536 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-11 19:11:17.682617 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.025)       0:00:13.206 *******
2026-03-11 19:11:17.682649 | controller | ok: [instance]
2026-03-11 19:11:22.716564 | controller |
2026-03-11 19:11:22.716615 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-11 19:11:22.716624 | controller | Wednesday 11 March 2026  19:11:17 +0000 (0:00:00.293)       0:00:13.499 *******
2026-03-11 19:11:22.716664 | controller | Pausing for 5 seconds
2026-03-11 19:11:23.029479 | controller | ok: [instance]
2026-03-11 19:11:23.029499 | controller |
2026-03-11 19:11:23.029507 | controller | TASK [Query mock state after eject] ********************************************
2026-03-11 19:11:23.029513 | controller | Wednesday 11 March 2026  19:11:22 +0000 (0:00:05.033)       0:00:18.532 *******
2026-03-11 19:11:23.029526 | controller | ok: [instance]
2026-03-11 19:11:23.062663 | controller |
2026-03-11 19:11:23.062682 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-03-11 19:11:23.062690 | controller | Wednesday 11 March 2026  19:11:23 +0000 (0:00:00.313)       0:00:18.846 *******
2026-03-11 19:11:23.062706 | controller | ok: [instance] => {
2026-03-11 19:11:23.373552 | controller |     "changed": false,
2026-03-11 19:11:23.373587 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:23.373602 | controller | }
2026-03-11 19:11:23.373612 | controller |
2026-03-11 19:11:23.373623 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-03-11 19:11:23.373672 | controller | Wednesday 11 March 2026  19:11:23 +0000 (0:00:00.033)       0:00:18.880 *******
2026-03-11 19:11:23.373682 | controller | ok: [instance]
2026-03-11 19:11:23.399817 | controller |
2026-03-11 19:11:23.399864 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-03-11 19:11:23.399874 | controller | Wednesday 11 March 2026  19:11:23 +0000 (0:00:00.310)       0:00:19.190 *******
2026-03-11 19:11:23.399889 | controller |
2026-03-11 19:11:23.695412 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-11 19:11:23.695440 | controller | Wednesday 11 March 2026  19:11:23 +0000 (0:00:00.026)       0:00:19.217 *******
2026-03-11 19:11:23.695452 | controller | ok: [instance]
2026-03-11 19:11:28.728820 | controller |
2026-03-11 19:11:28.728888 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-11 19:11:28.728899 | controller | Wednesday 11 March 2026  19:11:23 +0000 (0:00:00.295)       0:00:19.512 *******
2026-03-11 19:11:28.728916 | controller | Pausing for 5 seconds
2026-03-11 19:11:28.728949 | controller | ok: [instance]
2026-03-11 19:11:28.728977 | controller |
2026-03-11 19:11:28.728986 | controller | TASK [Query mock state] ********************************************************
2026-03-11 19:11:28.729155 | controller | Wednesday 11 March 2026  19:11:28 +0000 (0:00:05.033)       0:00:24.546 *******
2026-03-11 19:11:29.007454 | controller | ok: [instance]
2026-03-11 19:11:29.037930 | controller |
2026-03-11 19:11:29.038007 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-03-11 19:11:29.038022 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.278)       0:00:24.825 *******
2026-03-11 19:11:29.038044 | controller | ok: [instance] => {
2026-03-11 19:11:29.074408 | controller |     "changed": false,
2026-03-11 19:11:29.074441 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:29.074450 | controller | }
2026-03-11 19:11:29.074457 | controller |
2026-03-11 19:11:29.074463 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-03-11 19:11:29.074470 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.030)       0:00:24.855 *******
2026-03-11 19:11:29.074481 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_discover_vmedia.yml for instance
2026-03-11 19:11:29.358465 | controller |
2026-03-11 19:11:29.358490 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-11 19:11:29.358498 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.036)       0:00:24.892 *******
2026-03-11 19:11:29.358508 | controller | ok: [instance]
2026-03-11 19:11:29.394138 | controller |
2026-03-11 19:11:29.394156 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-03-11 19:11:29.394163 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.284)       0:00:25.176 *******
2026-03-11 19:11:29.394172 | controller |
2026-03-11 19:11:29.687823 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-11 19:11:29.687877 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.035)       0:00:25.211 *******
2026-03-11 19:11:29.687893 | controller | ok: [instance]
2026-03-11 19:11:29.687930 | controller |
2026-03-11 19:11:29.687941 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-11 19:11:31.115446 | controller | Wednesday 11 March 2026  19:11:29 +0000 (0:00:00.293)       0:00:25.505 *******
2026-03-11 19:11:31.115498 | controller | ok: [instance] => (item=Boot0001)
2026-03-11 19:11:31.159360 | controller | ok: [instance] => (item=Boot0003)
2026-03-11 19:11:31.159378 | controller | ok: [instance] => (item=Boot0004)
2026-03-11 19:11:31.159385 | controller | ok: [instance] => (item=Boot0005)
2026-03-11 19:11:31.159391 | controller | ok: [instance] => (item=Boot0006)
2026-03-11 19:11:31.159396 | controller |
2026-03-11 19:11:31.159402 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-11 19:11:31.159415 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:01.426)       0:00:26.932 *******
2026-03-11 19:11:31.159430 | controller | ok: [instance]
2026-03-11 19:11:31.186505 | controller |
2026-03-11 19:11:31.186523 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-11 19:11:31.186530 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.044)       0:00:26.976 *******
2026-03-11 19:11:31.186539 | controller | skipping: [instance]
2026-03-11 19:11:31.254861 | controller |
2026-03-11 19:11:31.254917 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-11 19:11:31.254931 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.026)       0:00:27.003 *******
2026-03-11 19:11:31.254950 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-11 19:11:31.280696 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-11 19:11:31.280733 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-03-11 19:11:31.280742 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-11 19:11:31.280748 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-11 19:11:31.280754 | controller |
2026-03-11 19:11:31.280760 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-11 19:11:31.280766 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.068)       0:00:27.072 *******
2026-03-11 19:11:31.280775 | controller | skipping: [instance]
2026-03-11 19:11:31.303614 | controller |
2026-03-11 19:11:31.303673 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-11 19:11:31.303682 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.025)       0:00:27.097 *******
2026-03-11 19:11:31.303692 | controller | ok: [instance] => {
2026-03-11 19:11:31.303856 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-11 19:11:31.303992 | controller | }
2026-03-11 19:11:31.304112 | controller |
2026-03-11 19:11:31.304240 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-11 19:11:31.304362 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.023)       0:00:27.121 *******
2026-03-11 19:11:31.593795 | controller | ok: [instance]
2026-03-11 19:11:31.593865 | controller |
2026-03-11 19:11:31.593897 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-11 19:11:31.594029 | controller | Wednesday 11 March 2026  19:11:31 +0000 (0:00:00.290)       0:00:27.411 *******
2026-03-11 19:11:41.631846 | controller | Pausing for 10 seconds
2026-03-11 19:11:41.920881 | controller | ok: [instance]
2026-03-11 19:11:41.920955 | controller |
2026-03-11 19:11:41.920964 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-11 19:11:41.920971 | controller | Wednesday 11 March 2026  19:11:41 +0000 (0:00:10.036)       0:00:37.447 *******
2026-03-11 19:11:41.920988 | controller | ok: [instance]
2026-03-11 19:11:42.217419 | controller |
2026-03-11 19:11:42.217479 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-11 19:11:42.217489 | controller | Wednesday 11 March 2026  19:11:41 +0000 (0:00:00.290)       0:00:37.738 *******
2026-03-11 19:11:42.217504 | controller | ok: [instance]
2026-03-11 19:11:42.247818 | controller |
2026-03-11 19:11:42.247871 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-11 19:11:42.247883 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.296)       0:00:38.034 *******
2026-03-11 19:11:42.247907 | controller | ok: [instance] => {
2026-03-11 19:11:42.247942 | controller |     "changed": false,
2026-03-11 19:11:42.247952 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:42.248216 | controller | }
2026-03-11 19:11:42.248250 | controller |
2026-03-11 19:11:42.543460 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-11 19:11:42.543485 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.030)       0:00:38.065 *******
2026-03-11 19:11:42.543496 | controller | ok: [instance]
2026-03-11 19:11:42.582823 | controller |
2026-03-11 19:11:42.582868 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-11 19:11:42.582896 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.295)       0:00:38.361 *******
2026-03-11 19:11:42.582913 | controller | ok: [instance] => {
2026-03-11 19:11:42.582961 | controller |     "changed": false,
2026-03-11 19:11:42.582973 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:42.582987 | controller | }
2026-03-11 19:11:42.583018 | controller |
2026-03-11 19:11:42.583204 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-03-11 19:11:42.623852 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.039)       0:00:38.400 *******
2026-03-11 19:11:42.623947 | controller | ok: [instance] => {
2026-03-11 19:11:42.926263 | controller |     "changed": false,
2026-03-11 19:11:42.926290 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:42.926300 | controller | }
2026-03-11 19:11:42.926306 | controller |
2026-03-11 19:11:42.926312 | controller | TASK [Query mock state after discover] *****************************************
2026-03-11 19:11:42.926319 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.040)       0:00:38.440 *******
2026-03-11 19:11:42.926329 | controller | ok: [instance]
2026-03-11 19:11:42.957790 | controller |
2026-03-11 19:11:42.957827 | controller | TASK [Assert boot override was set] ********************************************
2026-03-11 19:11:42.957840 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.303)       0:00:38.743 *******
2026-03-11 19:11:42.957856 | controller | ok: [instance] => {
2026-03-11 19:11:42.957899 | controller |     "changed": false,
2026-03-11 19:11:42.957909 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:42.957920 | controller | }
2026-03-11 19:11:42.957932 | controller |
2026-03-11 19:11:42.957966 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-11 19:11:42.957978 | controller | Wednesday 11 March 2026  19:11:42 +0000 (0:00:00.031)       0:00:38.775 *******
2026-03-11 19:11:43.277349 | controller | ok: [instance]
2026-03-11 19:11:43.312813 | controller |
2026-03-11 19:11:43.312876 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-03-11 19:11:43.312887 | controller | Wednesday 11 March 2026  19:11:43 +0000 (0:00:00.319)       0:00:39.095 *******
2026-03-11 19:11:43.312901 | controller |
2026-03-11 19:11:43.312939 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-11 19:11:43.313059 | controller | Wednesday 11 March 2026  19:11:43 +0000 (0:00:00.035)       0:00:39.130 *******
2026-03-11 19:11:43.621823 | controller | ok: [instance]
2026-03-11 19:11:43.621900 | controller |
2026-03-11 19:11:43.621914 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-11 19:11:43.621957 | controller | Wednesday 11 March 2026  19:11:43 +0000 (0:00:00.309)       0:00:39.439 *******
2026-03-11 19:11:45.046788 | controller | ok: [instance] => (item=Boot0001)
2026-03-11 19:11:45.047223 | controller | ok: [instance] => (item=Boot0003)
2026-03-11 19:11:45.047271 | controller | ok: [instance] => (item=Boot0004)
2026-03-11 19:11:45.047279 | controller | ok: [instance] => (item=Boot0005)
2026-03-11 19:11:45.047292 | controller | ok: [instance] => (item=Boot0006)
2026-03-11 19:11:45.087717 | controller |
2026-03-11 19:11:45.087749 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-11 19:11:45.087758 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:01.423)       0:00:40.863 *******
2026-03-11 19:11:45.087769 | controller | ok: [instance]
2026-03-11 19:11:45.087796 | controller |
2026-03-11 19:11:45.087804 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-11 19:11:45.087883 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.041)       0:00:40.905 *******
2026-03-11 19:11:45.134742 | controller | ok: [instance] => {
2026-03-11 19:11:45.135381 | controller |     "changed": false,
2026-03-11 19:11:45.200534 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:45.200556 | controller | }
2026-03-11 19:11:45.200564 | controller |
2026-03-11 19:11:45.200570 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-11 19:11:45.200576 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.047)       0:00:40.952 *******
2026-03-11 19:11:45.200585 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-11 19:11:45.227080 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-11 19:11:45.227099 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-03-11 19:11:45.227115 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-11 19:11:45.227122 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-11 19:11:45.227128 | controller | skipping: [instance]
2026-03-11 19:11:45.227135 | controller |
2026-03-11 19:11:45.227140 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-11 19:11:45.227146 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.065)       0:00:41.017 *******
2026-03-11 19:11:45.227154 | controller | skipping: [instance]
2026-03-11 19:11:45.227291 | controller |
2026-03-11 19:11:45.227427 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-11 19:11:45.227565 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.027)       0:00:41.045 *******
2026-03-11 19:11:45.251746 | controller | ok: [instance] => {
2026-03-11 19:11:45.251936 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-11 19:11:45.252076 | controller | }
2026-03-11 19:11:45.252203 | controller |
2026-03-11 19:11:45.252333 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-11 19:11:45.252459 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.024)       0:00:41.069 *******
2026-03-11 19:11:45.567812 | controller | ok: [instance]
2026-03-11 19:11:55.602937 | controller |
2026-03-11 19:11:55.603002 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-11 19:11:55.603016 | controller | Wednesday 11 March 2026  19:11:45 +0000 (0:00:00.315)       0:00:41.384 *******
2026-03-11 19:11:55.603037 | controller | Pausing for 10 seconds
2026-03-11 19:11:55.603070 | controller | ok: [instance]
2026-03-11 19:11:55.603081 | controller |
2026-03-11 19:11:55.603091 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-11 19:11:55.603104 | controller | Wednesday 11 March 2026  19:11:55 +0000 (0:00:10.034)       0:00:51.419 *******
2026-03-11 19:11:55.907455 | controller | ok: [instance]
2026-03-11 19:11:56.207021 | controller |
2026-03-11 19:11:56.207048 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-11 19:11:56.207057 | controller | Wednesday 11 March 2026  19:11:55 +0000 (0:00:00.305)       0:00:51.724 *******
2026-03-11 19:11:56.207067 | controller | ok: [instance]
2026-03-11 19:11:56.236692 | controller |
2026-03-11 19:11:56.236712 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-11 19:11:56.236719 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.299)       0:00:52.024 *******
2026-03-11 19:11:56.236729 | controller | ok: [instance] => {
2026-03-11 19:11:56.236914 | controller |     "changed": false,
2026-03-11 19:11:56.236930 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:56.236940 | controller | }
2026-03-11 19:11:56.236947 | controller |
2026-03-11 19:11:56.236957 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-11 19:11:56.535736 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.029)       0:00:52.054 *******
2026-03-11 19:11:56.535764 | controller | ok: [instance]
2026-03-11 19:11:56.578863 | controller |
2026-03-11 19:11:56.578924 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-11 19:11:56.578936 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.299)       0:00:52.353 *******
2026-03-11 19:11:56.578958 | controller | ok: [instance] => {
2026-03-11 19:11:56.578997 | controller |     "changed": false,
2026-03-11 19:11:56.579005 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:56.579016 | controller | }
2026-03-11 19:11:56.579198 | controller |
2026-03-11 19:11:56.579228 | controller | TASK [Query mock state] ********************************************************
2026-03-11 19:11:56.881825 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.042)       0:00:52.396 *******
2026-03-11 19:11:56.881886 | controller | ok: [instance]
2026-03-11 19:11:56.909527 | controller |
2026-03-11 19:11:56.909566 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-03-11 19:11:56.909575 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.303)       0:00:52.699 *******
2026-03-11 19:11:56.909585 | controller | ok: [instance] => {
2026-03-11 19:11:57.227767 | controller |     "changed": false,
2026-03-11 19:11:57.227812 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:57.227821 | controller | }
2026-03-11 19:11:57.227828 | controller |
2026-03-11 19:11:57.227835 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-11 19:11:57.227841 | controller | Wednesday 11 March 2026  19:11:56 +0000 (0:00:00.027)       0:00:52.726 *******
2026-03-11 19:11:57.227853 | controller | ok: [instance]
2026-03-11 19:11:57.261816 | controller |
2026-03-11 19:11:57.261865 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-03-11 19:11:57.261876 | controller | Wednesday 11 March 2026  19:11:57 +0000 (0:00:00.318)       0:00:53.045 *******
2026-03-11 19:11:57.261890 | controller |
2026-03-11 19:11:57.261899 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-11 19:11:57.261909 | controller | Wednesday 11 March 2026  19:11:57 +0000 (0:00:00.034)       0:00:53.079 *******
2026-03-11 19:11:57.559414 | controller | ok: [instance]
2026-03-11 19:11:58.984722 | controller |
2026-03-11 19:11:58.984766 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-11 19:11:58.984775 | controller | Wednesday 11 March 2026  19:11:57 +0000 (0:00:00.297)       0:00:53.376 *******
2026-03-11 19:11:58.984787 | controller | ok: [instance] => (item=Boot0001)
2026-03-11 19:11:58.984813 | controller | ok: [instance] => (item=Boot0003)
2026-03-11 19:11:58.984820 | controller | ok: [instance] => (item=Boot0004)
2026-03-11 19:11:58.984827 | controller | ok: [instance] => (item=Boot0005)
2026-03-11 19:11:58.985105 | controller | ok: [instance] => (item=Boot0006)
2026-03-11 19:11:58.985125 | controller |
2026-03-11 19:11:59.026758 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-11 19:11:59.026814 | controller | Wednesday 11 March 2026  19:11:58 +0000 (0:00:01.425)       0:00:54.801 *******
2026-03-11 19:11:59.026832 | controller | ok: [instance]
2026-03-11 19:11:59.026884 | controller |
2026-03-11 19:11:59.026915 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-11 19:11:59.027047 | controller | Wednesday 11 March 2026  19:11:59 +0000 (0:00:00.042)       0:00:54.844 *******
2026-03-11 19:11:59.067227 | controller | fatal: [instance]: FAILED! => {
2026-03-11 19:11:59.071988 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-03-11 19:11:59.072016 | controller |     "changed": false,
2026-03-11 19:11:59.072023 | controller |     "evaluated_to": false,
2026-03-11 19:11:59.072031 | controller |     "msg": "cifmw_bm_agent_vmedia_uefi_path 'PciRoot(0x0)/INVALID/PATH' is not listed in UEFI boot options. Available paths: PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA), Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1), Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0), Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi, Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-03-11 19:11:59.072038 | controller | }
2026-03-11 19:11:59.072047 | controller |
2026-03-11 19:11:59.121748 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-03-11 19:11:59.121789 | controller | Wednesday 11 March 2026  19:11:59 +0000 (0:00:00.044)       0:00:54.889 *******
2026-03-11 19:11:59.121803 | controller | ok: [instance] => {
2026-03-11 19:11:59.121874 | controller |     "changed": false,
2026-03-11 19:11:59.121883 | controller |     "msg": "All assertions passed"
2026-03-11 19:11:59.121890 | controller | }
2026-03-11 19:11:59.121896 | controller |
2026-03-11 19:11:59.121901 | controller | PLAY RECAP *********************************************************************
2026-03-11 19:11:59.121907 | controller | instance                   : ok=110  changed=0    unreachable=0    failed=0    skipped=12   rescued=5    ignored=0
2026-03-11 19:11:59.121913 | controller |
2026-03-11 19:11:59.121918 | controller | Wednesday 11 March 2026  19:11:59 +0000 (0:00:00.048)       0:00:54.938 *******
2026-03-11 19:11:59.121924 | controller | ===============================================================================
2026-03-11 19:11:59.121929 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.04s
2026-03-11 19:11:59.121939 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-11 19:11:59.121948 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-11 19:11:59.121972 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-11 19:11:59.122080 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.43s
2026-03-11 19:11:59.122180 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.43s
2026-03-11 19:11:59.122282 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.42s
2026-03-11 19:11:59.122379 | controller | Reset mock to power Off ------------------------------------------------- 0.42s
2026-03-11 19:11:59.122491 | controller | Query mock state after power_off (already off) -------------------------- 0.33s
2026-03-11 19:11:59.122590 | controller | Reset mock with VirtualMedia inserted ----------------------------------- 0.32s
2026-03-11 19:11:59.122727 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.32s
2026-03-11 19:11:59.122830 | controller | Reset mock with VirtualMedia inserted ----------------------------------- 0.32s
2026-03-11 19:11:59.122931 | controller | reproducer : Clear pending iDRAC config jobs that block boot override --- 0.32s
2026-03-11 19:11:59.123035 | controller | Query mock state after eject -------------------------------------------- 0.31s
2026-03-11 19:11:59.123137 | controller | reproducer : Query current power state ---------------------------------- 0.31s
2026-03-11 19:11:59.123238 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.31s
2026-03-11 19:11:59.123337 | controller | reproducer : Power on bare metal host ----------------------------------- 0.31s
2026-03-11 19:11:59.123436 | controller | Reset mock with VirtualMedia not inserted ------------------------------- 0.31s
2026-03-11 19:11:59.123536 | controller | reproducer : Wait for host POST to complete ----------------------------- 0.31s
2026-03-11 19:11:59.123658 | controller | reproducer : Fetch UEFI boot option IDs --------------------------------- 0.31s
2026-03-11 19:11:59.207144 | controller | INFO     Running bm_redfish > cleanup
2026-03-11 19:11:59.627102 | controller |
2026-03-11 19:11:59.627162 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-11 19:11:59.627269 | controller |
2026-03-11 19:11:59.627373 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-11 19:11:59.627473 | controller | Wednesday 11 March 2026  19:11:59 +0000 (0:00:00.021)       0:00:00.021 *******
2026-03-11 19:11:59.934028 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.014897", "end": "2026-03-11 19:11:59.907799", "msg": "non-zero return code", "rc": -15, "start": "2026-03-11 19:11:59.892902", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-11 19:11:59.936700 | controller |
2026-03-11 19:11:59.936778 | controller | PLAY RECAP *********************************************************************
2026-03-11 19:11:59.936794 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-11 19:11:59.936802 | controller |
2026-03-11 19:11:59.936808 | controller | Wednesday 11 March 2026  19:11:59 +0000 (0:00:00.310)       0:00:00.332 *******
2026-03-11 19:11:59.936814 | controller | ===============================================================================
2026-03-11 19:11:59.936823 | controller | Stop mock iDRAC server -------------------------------------------------- 0.31s
2026-03-11 19:12:00.003799 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/reproducer/bm_redfish/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/cleanup.yml']
2026-03-11 19:12:00.012135 | controller | WARNING  An error occurred during the test sequence action: 'cleanup'. Cleaning up.
2026-03-11 19:12:00.012158 | controller | INFO     Running bm_redfish > cleanup
2026-03-11 19:12:00.412049 | controller |
2026-03-11 19:12:00.412286 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-11 19:12:00.412484 | controller |
2026-03-11 19:12:00.412685 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-11 19:12:00.412804 | controller | Wednesday 11 March 2026  19:12:00 +0000 (0:00:00.022)       0:00:00.022 *******
2026-03-11 19:12:00.703742 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.015574", "end": "2026-03-11 19:12:00.680105", "msg": "non-zero return code", "rc": -15, "start": "2026-03-11 19:12:00.664531", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-11 19:12:00.705517 | controller |
2026-03-11 19:12:00.760750 | controller | PLAY RECAP *********************************************************************
2026-03-11 19:12:00.760791 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-11 19:12:00.760802 | controller |
2026-03-11 19:12:00.760810 | controller | Wednesday 11 March 2026  19:12:00 +0000 (0:00:00.294)       0:00:00.316 *******
2026-03-11 19:12:00.760817 | controller | ===============================================================================
2026-03-11 19:12:00.760824 | controller | Stop mock iDRAC server -------------------------------------------------- 0.29s
2026-03-11 19:12:00.760840 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/reproducer/bm_redfish/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/cleanup.yml']
2026-03-11 19:12:00.760988 | controller | INFO     Writing /tmp/report.html report.
2026-03-11 19:12:01.230920 | controller | ERROR
2026-03-11 19:12:01.231015 | controller | {
2026-03-11 19:12:01.231046 | controller |   "delta": "0:01:00.806933",
2026-03-11 19:12:01.231066 | controller |   "end": "2026-03-11 19:12:00.813732",
2026-03-11 19:12:01.231083 | controller |   "msg": "non-zero return code",
2026-03-11 19:12:01.231098 | controller |   "rc": 2,
2026-03-11 19:12:01.231113 | controller |   "start": "2026-03-11 19:11:00.006799"
2026-03-11 19:12:01.231128 | controller | }
failure
2026-03-11 19:12:01.274562 | 
2026-03-11 19:12:01.274633 | PLAY RECAP
2026-03-11 19:12:01.274685 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2026-03-11 19:12:01.274713 | 
2026-03-11 19:12:01.333959 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-11 19:12:01.334710 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-11 19:12:01.815883 | 
2026-03-11 19:12:01.815980 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-03-11 19:12:01.835181 | 
2026-03-11 19:12:01.835250 | TASK [Filter out host if needed]
2026-03-11 19:12:01.843035 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-03-11 19:12:01.847358 | 
2026-03-11 19:12:01.847420 | TASK [Ensure file is present]
2026-03-11 19:12:02.221489 | controller | ok
2026-03-11 19:12:02.226869 | 
2026-03-11 19:12:02.226938 | TASK [Manage molecule report file]
2026-03-11 19:12:02.751527 | controller | changed
2026-03-11 19:12:02.755990 | 
2026-03-11 19:12:02.756048 | TASK [Check if we get ci-framework-data basedir]
2026-03-11 19:12:03.027530 | controller | ok
2026-03-11 19:12:03.032114 | 
2026-03-11 19:12:03.032173 | TASK [Create ci-framework-data log directory for zuul]
2026-03-11 19:12:03.393979 | controller | changed
2026-03-11 19:12:03.398719 | 
2026-03-11 19:12:03.398782 | TASK [Copy ci-framework interesting files]
2026-03-11 19:12:03.662768 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-03-11 19:12:03.923365 | controller | changed
2026-03-11 19:12:03.927995 | 
2026-03-11 19:12:03.928054 | TASK [Get SELinux listing]
2026-03-11 19:12:04.452498 | controller | changed
2026-03-11 19:12:04.458140 | 
2026-03-11 19:12:04.458203 | TASK [Generate log index]
2026-03-11 19:12:05.663923 | controller | changed
2026-03-11 19:12:05.668663 | 
2026-03-11 19:12:05.668721 | TASK [Get some env related data]
2026-03-11 19:12:06.348568 | controller | /home/zuul/.local/bin/ansible
2026-03-11 19:12:07.196978 | controller | changed
2026-03-11 19:12:07.201710 | 
2026-03-11 19:12:07.201768 | TASK [Generate list of logs to collect in home directory]
2026-03-11 19:12:07.593463 | controller | ok: All paths examined
2026-03-11 19:12:07.598627 | 
2026-03-11 19:12:07.598688 | LOOP [Copy logs from home directory]
2026-03-11 19:12:08.217918 | controller | changed:
2026-03-11 19:12:08.218135 | controller | {
2026-03-11 19:12:08.218166 | controller |   "atime": 1772005405.932821,
2026-03-11 19:12:08.218186 | controller |   "ctime": 1772006396.9238591,
2026-03-11 19:12:08.218203 | controller |   "dev": 64513,
2026-03-11 19:12:08.218224 | controller |   "gid": 1000,
2026-03-11 19:12:08.218241 | controller |   "gr_name": "zuul",
2026-03-11 19:12:08.218256 | controller |   "inode": 2773,
2026-03-11 19:12:08.218297 | controller |   "isblk": false,
2026-03-11 19:12:08.218318 | controller |   "ischr": false,
2026-03-11 19:12:08.218334 | controller |   "isdir": false,
2026-03-11 19:12:08.218348 | controller |   "isfifo": false,
2026-03-11 19:12:08.218363 | controller |   "isgid": false,
2026-03-11 19:12:08.218377 | controller |   "islnk": false,
2026-03-11 19:12:08.218392 | controller |   "isreg": true,
2026-03-11 19:12:08.218406 | controller |   "issock": false,
2026-03-11 19:12:08.218420 | controller |   "isuid": false,
2026-03-11 19:12:08.218433 | controller |   "mode": "0644",
2026-03-11 19:12:08.218447 | controller |   "mtime": 1772006396.9238591,
2026-03-11 19:12:08.218461 | controller |   "nlink": 1,
2026-03-11 19:12:08.218475 | controller |   "path": "/home/zuul/crc-setup.log",
2026-03-11 19:12:08.218489 | controller |   "pw_name": "zuul",
2026-03-11 19:12:08.218504 | controller |   "rgrp": true,
2026-03-11 19:12:08.218519 | controller |   "roth": true,
2026-03-11 19:12:08.218533 | controller |   "rusr": true,
2026-03-11 19:12:08.218548 | controller |   "size": 4108,
2026-03-11 19:12:08.218562 | controller |   "uid": 1000,
2026-03-11 19:12:08.218576 | controller |   "wgrp": false,
2026-03-11 19:12:08.218599 | controller |   "woth": false,
2026-03-11 19:12:08.218617 | controller |   "wusr": true,
2026-03-11 19:12:08.218632 | controller |   "xgrp": false,
2026-03-11 19:12:08.218646 | controller |   "xoth": false,
2026-03-11 19:12:08.218660 | controller |   "xusr": false
2026-03-11 19:12:08.218673 | controller | }
2026-03-11 19:12:08.796088 | controller | changed:
2026-03-11 19:12:08.796182 | controller | {
2026-03-11 19:12:08.796208 | controller |   "atime": 1772006398.6759083,
2026-03-11 19:12:08.796228 | controller |   "ctime": 1772007098.5537844,
2026-03-11 19:12:08.796245 | controller |   "dev": 64513,
2026-03-11 19:12:08.796326 | controller |   "gid": 1000,
2026-03-11 19:12:08.796356 | controller |   "gr_name": "zuul",
2026-03-11 19:12:08.796376 | controller |   "inode": 359205,
2026-03-11 19:12:08.796394 | controller |   "isblk": false,
2026-03-11 19:12:08.796409 | controller |   "ischr": false,
2026-03-11 19:12:08.796424 | controller |   "isdir": false,
2026-03-11 19:12:08.796438 | controller |   "isfifo": false,
2026-03-11 19:12:08.796451 | controller |   "isgid": false,
2026-03-11 19:12:08.796465 | controller |   "islnk": false,
2026-03-11 19:12:08.796478 | controller |   "isreg": true,
2026-03-11 19:12:08.796491 | controller |   "issock": false,
2026-03-11 19:12:08.796505 | controller |   "isuid": false,
2026-03-11 19:12:08.796518 | controller |   "mode": "0644",
2026-03-11 19:12:08.796531 | controller |   "mtime": 1772007098.5537844,
2026-03-11 19:12:08.796545 | controller |   "nlink": 1,
2026-03-11 19:12:08.796567 | controller |   "path": "/home/zuul/crc-start.log",
2026-03-11 19:12:08.796581 | controller |   "pw_name": "zuul",
2026-03-11 19:12:08.796605 | controller |   "rgrp": true,
2026-03-11 19:12:08.796619 | controller |   "roth": true,
2026-03-11 19:12:08.796634 | controller |   "rusr": true,
2026-03-11 19:12:08.796647 | controller |   "size": 4654,
2026-03-11 19:12:08.796661 | controller |   "uid": 1000,
2026-03-11 19:12:08.796674 | controller |   "wgrp": false,
2026-03-11 19:12:08.796687 | controller |   "woth": false,
2026-03-11 19:12:08.796700 | controller |   "wusr": true,
2026-03-11 19:12:08.796713 | controller |   "xgrp": false,
2026-03-11 19:12:08.796726 | controller |   "xoth": false,
2026-03-11 19:12:08.796740 | controller |   "xusr": false
2026-03-11 19:12:08.796753 | controller | }
2026-03-11 19:12:09.368996 | controller | changed:
2026-03-11 19:12:09.369087 | controller | {
2026-03-11 19:12:09.369113 | controller |   "atime": 1773256241.0336063,
2026-03-11 19:12:09.369132 | controller |   "ctime": 1773256257.6197853,
2026-03-11 19:12:09.369150 | controller |   "dev": 64513,
2026-03-11 19:12:09.369172 | controller |   "gid": 1000,
2026-03-11 19:12:09.369189 | controller |   "gr_name": "zuul",
2026-03-11 19:12:09.369204 | controller |   "inode": 2751649,
2026-03-11 19:12:09.369219 | controller |   "isblk": false,
2026-03-11 19:12:09.369233 | controller |   "ischr": false,
2026-03-11 19:12:09.369248 | controller |   "isdir": false,
2026-03-11 19:12:09.369262 | controller |   "isfifo": false,
2026-03-11 19:12:09.369345 | controller |   "isgid": false,
2026-03-11 19:12:09.369366 | controller |   "islnk": false,
2026-03-11 19:12:09.369382 | controller |   "isreg": true,
2026-03-11 19:12:09.369397 | controller |   "issock": false,
2026-03-11 19:12:09.369413 | controller |   "isuid": false,
2026-03-11 19:12:09.369428 | controller |   "mode": "0644",
2026-03-11 19:12:09.369442 | controller |   "mtime": 1773256257.6197853,
2026-03-11 19:12:09.369456 | controller |   "nlink": 1,
2026-03-11 19:12:09.369470 | controller |   "path": "/home/zuul/ansible.log",
2026-03-11 19:12:09.369484 | controller |   "pw_name": "zuul",
2026-03-11 19:12:09.369499 | controller |   "rgrp": true,
2026-03-11 19:12:09.369513 | controller |   "roth": true,
2026-03-11 19:12:09.369529 | controller |   "rusr": true,
2026-03-11 19:12:09.369544 | controller |   "size": 6749,
2026-03-11 19:12:09.369557 | controller |   "uid": 1000,
2026-03-11 19:12:09.369571 | controller |   "wgrp": false,
2026-03-11 19:12:09.369593 | controller |   "woth": false,
2026-03-11 19:12:09.369609 | controller |   "wusr": true,
2026-03-11 19:12:09.369623 | controller |   "xgrp": false,
2026-03-11 19:12:09.369636 | controller |   "xoth": false,
2026-03-11 19:12:09.369650 | controller |   "xusr": false
2026-03-11 19:12:09.369663 | controller | }
2026-03-11 19:12:09.381869 | 
2026-03-11 19:12:09.381980 | TASK [Copy crio stats log file]
2026-03-11 19:12:09.395394 | controller | skipping: Conditional result was False
2026-03-11 19:12:09.400547 | 
2026-03-11 19:12:09.400618 | TASK [Get SELinux related data]
2026-03-11 19:12:09.692247 | controller | <no matches>
2026-03-11 19:12:09.927452 | controller | ERROR
2026-03-11 19:12:09.927652 | controller | {
2026-03-11 19:12:09.927692 | controller |   "delta": "0:00:00.009700",
2026-03-11 19:12:09.927718 | controller |   "end": "2026-03-11 19:12:09.693309",
2026-03-11 19:12:09.927741 | controller |   "msg": "non-zero return code",
2026-03-11 19:12:09.927763 | controller |   "rc": 1,
2026-03-11 19:12:09.927784 | controller |   "start": "2026-03-11 19:12:09.683609"
2026-03-11 19:12:09.927804 | controller | }
2026-03-11 19:12:09.927830 | controller | ERROR: Ignoring Errors
2026-03-11 19:12:09.932689 | 
2026-03-11 19:12:09.932755 | TASK [Create system configuration directory]
2026-03-11 19:12:10.214880 | controller | changed
2026-03-11 19:12:10.219912 | 
2026-03-11 19:12:10.219977 | TASK [Get some of the system configurations]
2026-03-11 19:12:10.745675 | controller | changed
2026-03-11 19:12:10.751096 | 
2026-03-11 19:12:10.751163 | TASK [Copy generated documentation if available]
2026-03-11 19:12:10.764309 | controller | skipping: Conditional result was False
2026-03-11 19:12:10.769777 | 
2026-03-11 19:12:10.769841 | TASK [Copy generated AsciiDoc documentation if available]
2026-03-11 19:12:10.782863 | controller | skipping: Conditional result was False
2026-03-11 19:12:10.787943 | 
2026-03-11 19:12:10.788006 | TASK [Compress logs bigger than 2MB]
2026-03-11 19:12:11.314553 | controller | changed
2026-03-11 19:12:11.319556 | 
2026-03-11 19:12:11.319627 | TASK [Copy files from workspace on node]
2026-03-11 19:12:11.336806 | controller | ok
2026-03-11 19:12:11.358110 | 
2026-03-11 19:12:11.358178 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-11 19:12:11.370776 | controller | skipping: Conditional result was False
2026-03-11 19:12:11.375981 | 
2026-03-11 19:12:11.376047 | TASK [fetch-output : Set log path for single node]
2026-03-11 19:12:11.403352 | controller | ok
2026-03-11 19:12:11.408133 | 
2026-03-11 19:12:11.408197 | LOOP [fetch-output : Ensure local output dirs]
2026-03-11 19:12:11.586559 | controller -> localhost | ok: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/logs"
2026-03-11 19:12:11.586808 | controller -> localhost | changed: All items complete
2026-03-11 19:12:11.586838 | 
2026-03-11 19:12:11.750198 | controller -> localhost | changed: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/artifacts"
2026-03-11 19:12:11.915476 | controller -> localhost | changed: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/docs"
2026-03-11 19:12:11.924010 | 
2026-03-11 19:12:11.924108 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-11 19:12:12.534119 | controller | changed:
2026-03-11 19:12:12.534278 | controller | .d..t...... ./
2026-03-11 19:12:12.534311 | controller | >f+++++++++ README.html
2026-03-11 19:12:12.534331 | controller | >f+++++++++ ansible-execution.log
2026-03-11 19:12:12.534349 | controller | >f+++++++++ ansible.log
2026-03-11 19:12:12.534365 | controller | >f+++++++++ crc-setup.log
2026-03-11 19:12:12.534381 | controller | >f+++++++++ crc-start.log
2026-03-11 19:12:12.534396 | controller | >f+++++++++ dmesg.log
2026-03-11 19:12:12.534414 | controller | >f+++++++++ installed-pkgs.log
2026-03-11 19:12:12.534429 | controller | >f+++++++++ python.log
2026-03-11 19:12:12.534443 | controller | >f+++++++++ registries.conf
2026-03-11 19:12:12.534457 | controller | >f+++++++++ report.html
2026-03-11 19:12:12.534472 | controller | >f+++++++++ selinux-denials.log
2026-03-11 19:12:12.534487 | controller | >f+++++++++ selinux-listing.log
2026-03-11 19:12:12.534501 | controller | cd+++++++++ ci-framework-data/
2026-03-11 19:12:12.534515 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-03-11 19:12:12.534529 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-03-11 19:12:12.534543 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-03-11 19:12:12.534557 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-03-11 19:12:12.534571 | controller | cd+++++++++ ci-framework-data/logs/
2026-03-11 19:12:12.534584 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-03-11 19:12:12.534611 | controller | cd+++++++++ registries.conf.d/
2026-03-11 19:12:12.534626 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-03-11 19:12:12.534640 | controller | cd+++++++++ system-config/
2026-03-11 19:12:12.534654 | controller | cd+++++++++ system-config/libvirt/
2026-03-11 19:12:12.534668 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-03-11 19:12:12.534683 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-03-11 19:12:12.534697 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2026-03-11 19:12:12.534711 | controller | >f+++++++++ system-config/libvirt/network.conf
2026-03-11 19:12:12.534724 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2026-03-11 19:12:12.534738 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2026-03-11 19:12:12.534751 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2026-03-11 19:12:12.534764 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2026-03-11 19:12:12.534779 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2026-03-11 19:12:12.534794 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2026-03-11 19:12:12.534809 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2026-03-11 19:12:12.534823 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2026-03-11 19:12:12.534837 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2026-03-11 19:12:12.534850 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2026-03-11 19:12:12.534863 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2026-03-11 19:12:12.534876 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2026-03-11 19:12:13.001155 | controller | changed: .d..t...... ./
2026-03-11 19:12:13.444485 | controller | changed: .d..t...... ./
2026-03-11 19:12:13.460027 | 
2026-03-11 19:12:13.460122 | TASK [Return artifact to Zuul]
2026-03-11 19:12:13.487634 | controller | ok
2026-03-11 19:12:13.505187 | 
2026-03-11 19:12:13.505236 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-03-11 19:12:13.505338 | 
2026-03-11 19:12:13.505367 | PLAY RECAP
2026-03-11 19:12:13.505402 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-03-11 19:12:13.505420 | 
2026-03-11 19:12:13.575500 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-11 19:12:13.576204 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-11 19:12:14.063508 | 
2026-03-11 19:12:14.063611 | PLAY [all]
2026-03-11 19:12:14.080929 | 
2026-03-11 19:12:14.080995 | TASK [include_role : fetch-output]
2026-03-11 19:12:14.108711 | controller | ok
2026-03-11 19:12:14.124515 | 
2026-03-11 19:12:14.124597 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-11 19:12:14.158745 | controller | skipping: Conditional result was False
2026-03-11 19:12:14.164036 | 
2026-03-11 19:12:14.164099 | TASK [fetch-output : Set log path for single node]
2026-03-11 19:12:14.191486 | controller | ok
2026-03-11 19:12:14.195904 | 
2026-03-11 19:12:14.195966 | LOOP [fetch-output : Ensure local output dirs]
2026-03-11 19:12:14.484866 | controller -> localhost | ok: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/logs"
2026-03-11 19:12:14.649295 | controller -> localhost | ok: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/artifacts"
2026-03-11 19:12:14.811804 | controller -> localhost | ok: "/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/docs"
2026-03-11 19:12:14.822177 | 
2026-03-11 19:12:14.822280 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-11 19:12:15.395986 | controller | ok
2026-03-11 19:12:15.396154 | controller | ok: All items complete
2026-03-11 19:12:15.396182 | 
2026-03-11 19:12:15.840794 | controller | ok
2026-03-11 19:12:16.293930 | controller | ok
2026-03-11 19:12:16.307510 | 
2026-03-11 19:12:16.307607 | TASK [include_role : fetch-output-openshift]
2026-03-11 19:12:16.320893 | controller | skipping: Conditional result was False
2026-03-11 19:12:16.326845 | 
2026-03-11 19:12:16.326910 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-03-11 19:12:16.632328 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.005866
2026-03-11 19:12:16.806440 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.005826
2026-03-11 19:12:16.837686 | 
2026-03-11 19:12:16.837758 | PLAY [all]
2026-03-11 19:12:16.850163 | 
2026-03-11 19:12:16.850226 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-03-11 19:12:17.305133 | controller | changed
2026-03-11 19:12:17.325620 | 
2026-03-11 19:12:17.325668 | PLAY RECAP
2026-03-11 19:12:17.325705 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-03-11 19:12:17.325725 | 
2026-03-11 19:12:17.388459 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-11 19:12:17.389125 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-03-11 19:12:17.876297 | 
2026-03-11 19:12:17.876397 | PLAY [localhost]
2026-03-11 19:12:17.892115 | 
2026-03-11 19:12:17.892184 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-03-11 19:12:18.162736 | localhost | changed
2026-03-11 19:12:18.166985 | 
2026-03-11 19:12:18.167059 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-03-11 19:12:18.184226 | localhost | ok
2026-03-11 19:12:18.191981 | 
2026-03-11 19:12:18.192059 | TASK [add-fileserver : Create SSH private key tempfile]
2026-03-11 19:12:18.452717 | localhost | changed
2026-03-11 19:12:18.457640 | 
2026-03-11 19:12:18.457704 | TASK [add-fileserver : Create SSH private key from secret]
2026-03-11 19:12:18.939487 | localhost | changed
2026-03-11 19:12:18.943998 | 
2026-03-11 19:12:18.944062 | TASK [add-fileserver : Add fileserver ssh key]
2026-03-11 19:12:19.244729 | localhost | Identity added: /var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/tmp/ansible.qnyqov8g (/var/lib/zuul/builds/035b126cee4e4e759d8cbe4da0f20dc5/work/tmp/ansible.qnyqov8g)
2026-03-11 19:12:19.244874 | localhost | ok: Runtime: 0:00:00.005484
2026-03-11 19:12:19.248757 | 
2026-03-11 19:12:19.248820 | TASK [add-fileserver : Remove SSH private key from disk]
2026-03-11 19:12:19.438016 | localhost | ok: Runtime: 0:00:00.003619
2026-03-11 19:12:19.442094 | 
2026-03-11 19:12:19.442153 | TASK [add-fileserver : Add fileserver to inventory]
2026-03-11 19:12:19.489243 | localhost | changed
2026-03-11 19:12:19.493615 | 
2026-03-11 19:12:19.493675 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-03-11 19:12:19.773377 | localhost | changed
2026-03-11 19:12:19.790812 | 
2026-03-11 19:12:19.790872 | PLAY [localhost]
2026-03-11 19:12:19.800957 | 
2026-03-11 19:12:19.801015 | TASK [Generate bulk log download script]
2026-03-11 19:12:19.817536 | localhost | ok
2026-03-11 19:12:19.828797 | 
2026-03-11 19:12:19.828858 | TASK [local-log-download : Check API endpoint is defined]
2026-03-11 19:12:19.855236 | localhost | ok: All assertions passed
2026-03-11 19:12:19.859716 | 
2026-03-11 19:12:19.859779 | TASK [local-log-download : Create download script]
2026-03-11 19:12:20.196535 | localhost -> localhost | changed
2026-03-11 19:12:20.204873 | 
2026-03-11 19:12:20.204945 | TASK [Register quick-download link]
2026-03-11 19:12:20.221685 | localhost | ok
2026-03-11 19:12:20.253555 | 
2026-03-11 19:12:20.253644 | PLAY [logserver.rdoproject.org]
2026-03-11 19:12:20.262645 | 
2026-03-11 19:12:20.262729 | TASK [Set zuul-log-path fact]
2026-03-11 19:12:20.278048 | logserver.rdoproject.org | ok
2026-03-11 19:12:20.286536 | 
2026-03-11 19:12:20.286612 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-11 19:12:20.301477 | logserver.rdoproject.org | ok
2026-03-11 19:12:20.306582 | 
2026-03-11 19:12:20.306660 | TASK [upload-logs : Create log directories]
2026-03-11 19:12:21.893558 | logserver.rdoproject.org | changed
2026-03-11 19:12:21.896496 | 
2026-03-11 19:12:21.896559 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-03-11 19:12:22.102630 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004367
2026-03-11 19:12:22.106712 | 
2026-03-11 19:12:22.106774 | TASK [upload-logs : Upload logs to log server]
2026-03-11 19:12:23.595238 | logserver.rdoproject.org | Output suppressed because no_log was given
2026-03-11 19:12:23.598156 | 
2026-03-11 19:12:23.598222 | LOOP [upload-logs : Compress console log and json output]
2026-03-11 19:12:23.650925 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-11 19:12:23.659737 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-11 19:12:23.666602 | 
2026-03-11 19:12:23.666681 | LOOP [upload-logs : Upload compressed console log and json output]
2026-03-11 19:12:23.712859 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-11 19:12:23.713102 | 
2026-03-11 19:12:23.715967 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-11 19:12:23.725499 | 
2026-03-11 19:12:23.725570 | LOOP [upload-logs : Upload console log and json output]