2026-06-08 13:06:08.423821 | Job console starting
2026-06-08 13:06:08.543143 | Updating git repos
2026-06-08 13:06:08.598308 | Cloning repos into workspace
2026-06-08 13:06:10.895674 | Restoring repo states
2026-06-08 13:06:10.918318 | Merging changes
2026-06-08 13:06:12.414243 | Checking out repos
2026-06-08 13:06:13.140101 | Preparing playbooks
2026-06-08 13:06:17.573448 | Running Ansible setup
2026-06-08 13:06:21.700432 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 13:06:22.369008 | 
2026-06-08 13:06:22.369112 | PLAY [localhost]
2026-06-08 13:06:22.376176 | 
2026-06-08 13:06:22.376242 | TASK [Gathering Facts]
2026-06-08 13:06:23.329390 | localhost | ok
2026-06-08 13:06:23.342610 | 
2026-06-08 13:06:23.342786 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-06-08 13:06:23.792301 | localhost -> localhost | changed
2026-06-08 13:06:23.801385 | 
2026-06-08 13:06:23.801755 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-06-08 13:06:24.816135 | localhost -> localhost | changed
2026-06-08 13:06:24.829766 | 
2026-06-08 13:06:24.829916 | TASK [Setup log path fact]
2026-06-08 13:06:24.853259 | localhost | ok
2026-06-08 13:06:24.875079 | 
2026-06-08 13:06:24.875227 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 13:06:24.916545 | localhost | ok
2026-06-08 13:06:24.929597 | 
2026-06-08 13:06:24.929741 | TASK [emit-job-header : Print job information]
2026-06-08 13:06:24.981350 | # Job Information
2026-06-08 13:06:24.981653 | Ansible Version: 2.16.18
2026-06-08 13:06:24.981714 | Job: cifmw-molecule-bm_sno
2026-06-08 13:06:24.981758 | Pipeline: github-check
2026-06-08 13:06:24.981799 | Executor: 38.102.83.32
2026-06-08 13:06:24.981840 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3982
2026-06-08 13:06:24.981882 | Log URL (when completed): https://gateway-cloud-softwarefactory.apps.ocp.cloud.ci.centos.org/logs/4f0/rdoproject.org/4f0216a1de4d414d87eb5cbc8d9eea3b/
2026-06-08 13:06:24.981926 | Event ID: cc885080-6338-11f1-99f0-62af3803e247
2026-06-08 13:06:24.988026 | 
2026-06-08 13:06:24.988419 | LOOP [emit-job-header : Print node information]
2026-06-08 13:06:25.132945 | localhost | ok:
2026-06-08 13:06:25.133223 | localhost | # Node Information
2026-06-08 13:06:25.133280 | localhost | Inventory Hostname: controller
2026-06-08 13:06:25.133325 | localhost | Hostname: np0000067266
2026-06-08 13:06:25.133364 | localhost | Username: zuul
2026-06-08 13:06:25.133405 | localhost | Distro: CentOS 9
2026-06-08 13:06:25.133443 | localhost | Provider: vexxhost-nodepool-tripleo
2026-06-08 13:06:25.133479 | localhost | Region: RegionOne
2026-06-08 13:06:25.133550 | localhost | Label: cloud-centos-9-stream-tripleo
2026-06-08 13:06:25.133597 | localhost | Product Name: OpenStack Nova
2026-06-08 13:06:25.133634 | localhost | Interface IP: 38.102.83.36
2026-06-08 13:06:25.145704 | 
2026-06-08 13:06:25.145873 | PLAY [all]
2026-06-08 13:06:25.156707 | 
2026-06-08 13:06:25.156836 | TASK [Gather network facts]
2026-06-08 13:06:25.597188 | controller | ok
2026-06-08 13:06:25.609348 | 
2026-06-08 13:06:25.609470 | TASK [include_role : start-zuul-console]
2026-06-08 13:06:25.634970 | controller | ok
2026-06-08 13:06:25.654075 | 
2026-06-08 13:06:25.654233 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-06-08 13:06:26.050704 | controller | ok
2026-06-08 13:06:26.062895 | 
2026-06-08 13:06:26.063021 | TASK [include_role : add-build-sshkey]
2026-06-08 13:06:26.095471 | controller | ok
2026-06-08 13:06:26.116925 | 
2026-06-08 13:06:26.117057 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-06-08 13:06:26.408063 | controller -> localhost | ok
2026-06-08 13:06:26.418365 | 
2026-06-08 13:06:26.418497 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-06-08 13:06:26.453122 | controller | ok
2026-06-08 13:06:26.479171 | controller | included: /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-06-08 13:06:26.489404 | 
2026-06-08 13:06:26.489557 | TASK [add-build-sshkey : Create Temp SSH key]
2026-06-08 13:06:27.181152 | controller -> localhost | Generating public/private rsa key pair.
2026-06-08 13:06:27.181410 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/4f0216a1de4d414d87eb5cbc8d9eea3b_id_rsa
2026-06-08 13:06:27.181474 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/4f0216a1de4d414d87eb5cbc8d9eea3b_id_rsa.pub
2026-06-08 13:06:27.181564 | controller -> localhost | The key fingerprint is:
2026-06-08 13:06:27.181627 | controller -> localhost | SHA256:yNg8Mgl0DLK0gwRZHyI8UJp31bJdZnVkUbicVdqgA28 zuul-build-sshkey
2026-06-08 13:06:27.181673 | controller -> localhost | The key's randomart image is:
2026-06-08 13:06:27.181713 | controller -> localhost | +---[RSA 3072]----+
2026-06-08 13:06:27.181753 | controller -> localhost | |O**oo ..  ....*++|
2026-06-08 13:06:27.181794 | controller -> localhost | |=X.+.o. . +o +.+.|
2026-06-08 13:06:27.181836 | controller -> localhost | |=o+ o  + +  E..+.|
2026-06-08 13:06:27.181876 | controller -> localhost | | ..o *...  . .+  |
2026-06-08 13:06:27.181915 | controller -> localhost | |    = * S        |
2026-06-08 13:06:27.181953 | controller -> localhost | |     o .         |
2026-06-08 13:06:27.181992 | controller -> localhost | |                 |
2026-06-08 13:06:27.182031 | controller -> localhost | |                 |
2026-06-08 13:06:27.182068 | controller -> localhost | |                 |
2026-06-08 13:06:27.182106 | controller -> localhost | +----[SHA256]-----+
2026-06-08 13:06:27.182192 | controller -> localhost | ok: Runtime: 0:00:00.203525
2026-06-08 13:06:27.190091 | 
2026-06-08 13:06:27.190210 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-06-08 13:06:27.211768 | controller | ok
2026-06-08 13:06:27.228107 | controller | included: /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-06-08 13:06:27.242188 | 
2026-06-08 13:06:27.242302 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-06-08 13:06:27.256883 | controller | skipping: Conditional result was False
2026-06-08 13:06:27.262254 | 
2026-06-08 13:06:27.262340 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-06-08 13:06:27.695966 | controller | changed
2026-06-08 13:06:27.701117 | 
2026-06-08 13:06:27.701205 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-06-08 13:06:27.930592 | controller | ok
2026-06-08 13:06:27.933839 | 
2026-06-08 13:06:27.933897 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-06-08 13:06:28.675891 | controller | changed
2026-06-08 13:06:28.682975 | 
2026-06-08 13:06:28.683163 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-06-08 13:06:29.514851 | controller | changed
2026-06-08 13:06:29.524169 | 
2026-06-08 13:06:29.524302 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-06-08 13:06:29.549706 | controller | skipping: Conditional result was False
2026-06-08 13:06:29.558733 | 
2026-06-08 13:06:29.558871 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-06-08 13:06:29.992840 | controller -> localhost | changed
2026-06-08 13:06:30.005419 | 
2026-06-08 13:06:30.005579 | TASK [add-build-sshkey : Add back temp key]
2026-06-08 13:06:30.331418 | controller -> localhost | Identity added: /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/4f0216a1de4d414d87eb5cbc8d9eea3b_id_rsa (zuul-build-sshkey)
2026-06-08 13:06:30.331742 | controller -> localhost | ok: Runtime: 0:00:00.017332
2026-06-08 13:06:30.340817 | 
2026-06-08 13:06:30.340941 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-06-08 13:06:30.698028 | controller | ok
2026-06-08 13:06:30.702080 | 
2026-06-08 13:06:30.702158 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-06-08 13:06:30.736441 | controller | skipping: Conditional result was False
2026-06-08 13:06:30.745085 | 
2026-06-08 13:06:30.745164 | TASK [include_role : validate-host]
2026-06-08 13:06:30.775066 | controller | ok
2026-06-08 13:06:30.796221 | 
2026-06-08 13:06:30.796308 | TASK [validate-host : Define zuul_info_dir fact]
2026-06-08 13:06:30.835155 | controller | ok
2026-06-08 13:06:30.839296 | 
2026-06-08 13:06:30.839379 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-06-08 13:06:31.144757 | controller -> localhost | ok
2026-06-08 13:06:31.154220 | 
2026-06-08 13:06:31.154357 | TASK [validate-host : Collect information about the host]
2026-06-08 13:06:31.809061 | controller | ok
2026-06-08 13:06:31.825998 | 
2026-06-08 13:06:31.826200 | TASK [validate-host : Sanitize hostname]
2026-06-08 13:06:31.899231 | controller | ok
2026-06-08 13:06:31.906353 | 
2026-06-08 13:06:31.906497 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-06-08 13:06:32.406345 | controller -> localhost | changed
2026-06-08 13:06:32.411963 | 
2026-06-08 13:06:32.412031 | TASK [validate-host : Collect information about zuul worker]
2026-06-08 13:06:32.855326 | controller | ok
2026-06-08 13:06:32.858794 | 
2026-06-08 13:06:32.858854 | TASK [validate-host : Write out all zuul information for each host]
2026-06-08 13:06:33.291793 | controller -> localhost | changed
2026-06-08 13:06:33.306303 | 
2026-06-08 13:06:33.306424 | TASK [include_role : prepare-workspace-openshift]
2026-06-08 13:06:33.323903 | controller | skipping: Conditional result was False
2026-06-08 13:06:33.331763 | 
2026-06-08 13:06:33.331887 | TASK [include_role : remove-zuul-sshkey]
2026-06-08 13:06:33.357328 | controller | skipping: Conditional result was False
2026-06-08 13:06:33.365376 | 
2026-06-08 13:06:33.365501 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-06-08 13:06:33.617148 | controller | ok: "logs"
2026-06-08 13:06:33.617744 | controller | ok: All items complete
2026-06-08 13:06:33.617846 | 
2026-06-08 13:06:33.850384 | controller | ok: "artifacts"
2026-06-08 13:06:34.070506 | controller | ok: "docs"
2026-06-08 13:06:34.087003 | 
2026-06-08 13:06:34.087199 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-06-08 13:06:34.350812 | controller | changed: "logs"
2026-06-08 13:06:34.581371 | controller | changed: "artifacts"
2026-06-08 13:06:34.790044 | controller | changed: "docs"
2026-06-08 13:06:34.799240 | 
2026-06-08 13:06:34.799362 | PLAY RECAP
2026-06-08 13:06:34.799424 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 13:06:34.799462 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 13:06:34.799487 | 
2026-06-08 13:06:34.938963 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 13:06:34.941228 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 13:06:35.583131 | 
2026-06-08 13:06:35.583228 | PLAY [all]
2026-06-08 13:06:35.593180 | 
2026-06-08 13:06:35.593252 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 13:06:35.674656 | controller | ok
2026-06-08 13:06:35.682024 | 
2026-06-08 13:06:35.682178 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 13:06:36.236549 | controller | changed
2026-06-08 13:06:36.246136 | 
2026-06-08 13:06:36.246273 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 13:06:37.318048 | controller | changed
2026-06-08 13:06:37.335170 | 
2026-06-08 13:06:37.335327 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-06-08 13:06:37.791144 | controller | changed:
2026-06-08 13:06:37.791422 | controller | {
2026-06-08 13:06:37.791477 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-06-08 13:06:37.791562 | controller | }
2026-06-08 13:06:38.084280 | controller | changed:
2026-06-08 13:06:38.084416 | controller | {
2026-06-08 13:06:38.084469 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-06-08 13:06:38.084510 | controller | }
2026-06-08 13:06:38.333989 | controller | changed:
2026-06-08 13:06:38.334088 | controller | {
2026-06-08 13:06:38.334111 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2026-06-08 13:06:38.334128 | controller | }
2026-06-08 13:06:38.629846 | controller | changed:
2026-06-08 13:06:38.630051 | controller | {
2026-06-08 13:06:38.630103 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-06-08 13:06:38.630142 | controller | }
2026-06-08 13:06:38.891966 | controller | changed:
2026-06-08 13:06:38.892120 | controller | {
2026-06-08 13:06:38.892181 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-06-08 13:06:38.892229 | controller | }
2026-06-08 13:06:39.409946 | controller | changed:
2026-06-08 13:06:39.410100 | controller | {
2026-06-08 13:06:39.410165 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-06-08 13:06:39.410215 | controller | }
2026-06-08 13:06:40.142855 | controller | changed:
2026-06-08 13:06:40.143012 | controller | {
2026-06-08 13:06:40.143067 | 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-06-08 13:06:40.143111 | controller | }
2026-06-08 13:06:41.029590 | controller | changed:
2026-06-08 13:06:41.029722 | controller | {
2026-06-08 13:06:41.029775 | 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-06-08 13:06:41.029832 | controller | }
2026-06-08 13:06:41.297060 | controller | changed:
2026-06-08 13:06:41.297282 | controller | {
2026-06-08 13:06:41.297339 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-06-08 13:06:41.297380 | controller | }
2026-06-08 13:06:41.571924 | controller | changed:
2026-06-08 13:06:41.572057 | controller | {
2026-06-08 13:06:41.572108 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-06-08 13:06:41.572148 | controller | }
2026-06-08 13:06:42.406344 | controller | changed:
2026-06-08 13:06:42.406651 | controller | {
2026-06-08 13:06:42.406715 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-06-08 13:06:42.406756 | controller | }
2026-06-08 13:06:44.105981 | controller | changed:
2026-06-08 13:06:44.106076 | controller | {
2026-06-08 13:06:44.106108 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-06-08 13:06:44.106132 | controller | }
2026-06-08 13:06:44.426544 | controller | changed:
2026-06-08 13:06:44.426664 | controller | {
2026-06-08 13:06:44.426713 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-06-08 13:06:44.426752 | controller | }
2026-06-08 13:06:44.787723 | controller | changed:
2026-06-08 13:06:44.787866 | controller | {
2026-06-08 13:06:44.787917 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-06-08 13:06:44.787987 | controller | }
2026-06-08 13:06:45.058231 | controller | changed:
2026-06-08 13:06:45.058350 | controller | {
2026-06-08 13:06:45.058409 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-06-08 13:06:45.058460 | controller | }
2026-06-08 13:06:45.313566 | controller | changed:
2026-06-08 13:06:45.313815 | controller | {
2026-06-08 13:06:45.313876 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-06-08 13:06:45.313918 | controller | }
2026-06-08 13:06:45.606469 | controller | changed:
2026-06-08 13:06:45.606620 | controller | {
2026-06-08 13:06:45.606671 | 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-06-08 13:06:45.606711 | controller | }
2026-06-08 13:06:45.879458 | controller | changed:
2026-06-08 13:06:45.879627 | controller | {
2026-06-08 13:06:45.879682 | 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-06-08 13:06:45.879742 | controller | }
2026-06-08 13:06:46.156329 | controller | changed:
2026-06-08 13:06:46.156474 | controller | {
2026-06-08 13:06:46.156561 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-06-08 13:06:46.156604 | controller | }
2026-06-08 13:06:46.415960 | controller | changed:
2026-06-08 13:06:46.416094 | controller | {
2026-06-08 13:06:46.416143 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-06-08 13:06:46.416182 | controller | }
2026-06-08 13:06:46.691955 | controller | changed:
2026-06-08 13:06:46.692091 | controller | {
2026-06-08 13:06:46.692141 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-06-08 13:06:46.692181 | controller | }
2026-06-08 13:06:46.947122 | controller | changed:
2026-06-08 13:06:46.947218 | controller | {
2026-06-08 13:06:46.947249 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-06-08 13:06:46.947274 | controller | }
2026-06-08 13:06:47.210947 | controller | changed:
2026-06-08 13:06:47.211093 | controller | {
2026-06-08 13:06:47.211145 | 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-06-08 13:06:47.211185 | controller | }
2026-06-08 13:06:47.459404 | controller | changed:
2026-06-08 13:06:47.459574 | controller | {
2026-06-08 13:06:47.459633 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-06-08 13:06:47.459677 | controller | }
2026-06-08 13:06:47.749451 | controller | changed:
2026-06-08 13:06:47.749633 | controller | {
2026-06-08 13:06:47.749684 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-06-08 13:06:47.749721 | controller | }
2026-06-08 13:06:48.020508 | controller | changed:
2026-06-08 13:06:48.020728 | controller | {
2026-06-08 13:06:48.020780 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-06-08 13:06:48.020819 | controller | }
2026-06-08 13:06:48.059270 | 
2026-06-08 13:06:48.059425 | TASK [Set timezone to UTC]
2026-06-08 13:06:48.569496 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-06-08 13:06:48.577011 | 
2026-06-08 13:06:48.577145 | TASK [Create nodepool directory]
2026-06-08 13:06:48.844123 | controller | changed
2026-06-08 13:06:48.854439 | 
2026-06-08 13:06:48.854613 | TASK [Create nodepool sub_nodes file]
2026-06-08 13:06:49.586653 | controller | changed
2026-06-08 13:06:49.594008 | 
2026-06-08 13:06:49.594142 | TASK [Create nodepool sub_nodes_private file]
2026-06-08 13:06:50.265782 | controller | changed
2026-06-08 13:06:50.273707 | 
2026-06-08 13:06:50.273832 | LOOP [Populate nodepool sub_nodes file]
2026-06-08 13:06:50.318170 | 
2026-06-08 13:06:50.318431 | LOOP [Populate nodepool sub_nodes_private file]
2026-06-08 13:06:50.375033 | 
2026-06-08 13:06:50.375302 | TASK [Create nodepool primary file]
2026-06-08 13:06:50.400696 | controller | skipping: Conditional result was False
2026-06-08 13:06:50.409085 | 
2026-06-08 13:06:50.409221 | TASK [Create nodepool node_private for this node]
2026-06-08 13:06:51.245449 | controller | changed
2026-06-08 13:06:51.254589 | 
2026-06-08 13:06:51.254713 | LOOP [Copy ssh keys to nodepool directory]
2026-06-08 13:06:51.659830 | controller | ok: Item: id_rsa Runtime: 0:00:00.007439
2026-06-08 13:06:51.660189 | 
2026-06-08 13:06:51.893673 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005786
2026-06-08 13:06:51.903257 | 
2026-06-08 13:06:51.903386 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-06-08 13:06:52.614130 | controller | changed
2026-06-08 13:06:52.621387 | 
2026-06-08 13:06:52.621506 | TASK [Validate sudoers config after edits]
2026-06-08 13:06:52.934912 | controller | /etc/sudoers: parsed OK
2026-06-08 13:06:52.935080 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-06-08 13:06:52.935093 | controller | /etc/sudoers.d/zuul: parsed OK
2026-06-08 13:06:52.935099 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-06-08 13:06:53.168965 | controller | ok: Runtime: 0:00:00.007911
2026-06-08 13:06:53.176687 | 
2026-06-08 13:06:53.176806 | TASK [Show the environment passed in to job shell scripts]
2026-06-08 13:06:53.468953 | controller | SHELL=/bin/bash
2026-06-08 13:06:53.469013 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-06-08 13:06:53.469019 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-06-08 13:06:53.469026 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/82/3982/af553a87f5b4926bd998609e954d791a3d8d2c70
2026-06-08 13:06:53.469031 | controller | PWD=/home/zuul
2026-06-08 13:06:53.469035 | controller | ZUUL_PIPELINE=github-check
2026-06-08 13:06:53.469041 | controller | LOGNAME=zuul
2026-06-08 13:06:53.469045 | controller | XDG_SESSION_TYPE=tty
2026-06-08 13:06:53.469048 | controller | _=/usr/bin/env
2026-06-08 13:06:53.469053 | controller | MOTD_SHOWN=pam
2026-06-08 13:06:53.469056 | controller | HOME=/home/zuul
2026-06-08 13:06:53.469060 | controller | LANG=en_US.UTF-8
2026-06-08 13:06:53.469064 | controller | SSH_CONNECTION=38.102.83.32 50606 38.102.83.36 22
2026-06-08 13:06:53.469068 | 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-06-08 13:06:53.469073 | controller | ZUUL_CHANGE_IDS=3982,af553a87f5b4926bd998609e954d791a3d8d2c70
2026-06-08 13:06:53.469080 | controller | WORKSPACE=/home/zuul/workspace
2026-06-08 13:06:53.469089 | controller | XDG_SESSION_CLASS=user
2026-06-08 13:06:53.469093 | controller | SELINUX_ROLE_REQUESTED=
2026-06-08 13:06:53.469101 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-06-08 13:06:53.469184 | controller | USER=zuul
2026-06-08 13:06:53.469190 | controller | ZUUL_VOTING=True
2026-06-08 13:06:53.469193 | controller | BUILD_TIMEOUT=1800000
2026-06-08 13:06:53.469197 | controller | SELINUX_USE_CURRENT_RANGE=
2026-06-08 13:06:53.469200 | controller | SHLVL=1
2026-06-08 13:06:53.469204 | controller | ZUUL_PATCHSET=af553a87f5b4926bd998609e954d791a3d8d2c70
2026-06-08 13:06:53.469208 | controller | XDG_SESSION_ID=1
2026-06-08 13:06:53.469211 | controller | ZUUL_BRANCH=main
2026-06-08 13:06:53.469214 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-06-08 13:06:53.469218 | controller | SSH_CLIENT=38.102.83.32 50606 22
2026-06-08 13:06:53.469224 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-06-08 13:06:53.469228 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-06-08 13:06:53.469231 | controller | which_declare=declare -f
2026-06-08 13:06:53.469235 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2026-06-08 13:06:53.469239 | controller | SELINUX_LEVEL_REQUESTED=
2026-06-08 13:06:53.469242 | controller | ZUUL_CHANGE=3982
2026-06-08 13:06:53.469245 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-06-08 13:06:53.469249 | controller | ZUUL_UUID=4f0216a1de4d414d87eb5cbc8d9eea3b
2026-06-08 13:06:53.469253 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-06-08 13:06:53.469256 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-06-08 13:06:53.469260 | controller | }
2026-06-08 13:06:53.720618 | controller | ok: Runtime: 0:00:00.008937
2026-06-08 13:06:53.728438 | 
2026-06-08 13:06:53.728601 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-06-08 13:06:53.754317 | controller | skipping: Conditional result was False
2026-06-08 13:06:53.762869 | 
2026-06-08 13:06:53.762994 | TASK [Symlink /home/zuul-worker/workspace]
2026-06-08 13:06:54.297043 | controller | skipping: Conditional result was False
2026-06-08 13:06:54.305721 | 
2026-06-08 13:06:54.305850 | TASK [Ensure legacy workspace directory]
2026-06-08 13:06:54.592191 | controller | changed
2026-06-08 13:06:54.594859 | 
2026-06-08 13:06:54.594960 | PLAY RECAP
2026-06-08 13:06:54.595045 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 13:06:54.595087 | 
2026-06-08 13:06:54.716136 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 13:06:54.718480 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 13:06:55.312556 | 
2026-06-08 13:06:55.312653 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-06-08 13:06:55.324482 | 
2026-06-08 13:06:55.324587 | TASK [Create zuul-output directory]
2026-06-08 13:06:55.701630 | controller | changed
2026-06-08 13:06:55.710984 | 
2026-06-08 13:06:55.711163 | TASK [Slurp Zuul inventory test]
2026-06-08 13:06:56.173590 | controller -> localhost | ok
2026-06-08 13:06:56.184025 | 
2026-06-08 13:06:56.184157 | TASK [Save zuul inventory]
2026-06-08 13:06:57.241185 | controller | changed
2026-06-08 13:06:57.248802 | 
2026-06-08 13:06:57.248940 | TASK [Save zuul vars without the change_message]
2026-06-08 13:06:58.062898 | controller | changed
2026-06-08 13:06:58.065432 | 
2026-06-08 13:06:58.065580 | PLAY RECAP
2026-06-08 13:06:58.065677 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 13:06:58.065723 | 
2026-06-08 13:06:58.180646 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 13:06:58.182878 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 13:06:58.824592 | 
2026-06-08 13:06:58.824691 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-06-08 13:06:58.837054 | 
2026-06-08 13:06:58.837146 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-06-08 13:06:58.854239 | controller | ok
2026-06-08 13:06:58.867935 | 
2026-06-08 13:06:58.868012 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 13:06:58.891474 | controller | skipping: Conditional result was False
2026-06-08 13:06:58.895853 | 
2026-06-08 13:06:58.895920 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 13:06:59.271939 | controller | ok
2026-06-08 13:06:59.280633 | 
2026-06-08 13:06:59.280765 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 13:07:00.313195 | controller | ok
2026-06-08 13:07:00.329452 | 
2026-06-08 13:07:00.329650 | TASK [Prepare workspace]
2026-06-08 13:07:00.354190 | controller | ok
2026-06-08 13:07:00.386463 | 
2026-06-08 13:07:00.386580 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-06-08 13:07:00.794311 | controller | ok
2026-06-08 13:07:00.798732 | 
2026-06-08 13:07:00.798791 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-06-08 13:07:02.755150 | controller | Output suppressed because no_log was given
2026-06-08 13:07:02.764112 | 
2026-06-08 13:07:02.764266 | LOOP [Create zuul-output directory]
2026-06-08 13:07:02.985857 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-06-08 13:07:03.174538 | controller | ok: "/home/zuul/zuul-output/logs"
2026-06-08 13:07:03.188459 | 
2026-06-08 13:07:03.188671 | TASK [Install required packages]
2026-06-08 13:08:05.744880 | controller | changed
2026-06-08 13:08:05.753044 | 
2026-06-08 13:08:05.753163 | TASK [Install venv]
2026-06-08 13:09:35.820155 | controller | changed
2026-06-08 13:09:35.831407 | 
2026-06-08 13:09:35.831497 | PLAY RECAP
2026-06-08 13:09:35.831566 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 13:09:35.831589 | 
2026-06-08 13:09:35.966415 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 13:09:35.967814 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 13:09:36.580272 | 
2026-06-08 13:09:36.580406 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-06-08 13:09:36.595272 | 
2026-06-08 13:09:36.595353 | TASK [Gather required facts]
2026-06-08 13:09:37.300830 | controller | ok
2026-06-08 13:09:37.309825 | 
2026-06-08 13:09:37.309978 | TASK [Load environment var if instructed to]
2026-06-08 13:09:37.346425 | controller | skipping: Conditional result was False
2026-06-08 13:09:37.354810 | 
2026-06-08 13:09:37.354949 | TASK [Ensure group_vars dir exists]
2026-06-08 13:09:37.820052 | controller | ok
2026-06-08 13:09:37.825568 | 
2026-06-08 13:09:37.825652 | TASK [Print related variables]
2026-06-08 13:09:37.869050 | controller | ok:
2026-06-08 13:09:37.869286 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-06-08 13:09:37.869334 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno
2026-06-08 13:09:37.875859 | 
2026-06-08 13:09:37.875966 | TASK [Run molecule]
2026-06-08 13:09:39.027680 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-06-08 13:09:39.120920 | controller | INFO     Running bm_redfish > prepare
2026-06-08 13:09:39.868568 | controller |
2026-06-08 13:09:39.868635 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-06-08 13:09:39.868759 | controller |
2026-06-08 13:09:39.868878 | controller | TASK [Create mock server directory] ********************************************
2026-06-08 13:09:39.869553 | controller | Monday 08 June 2026  13:09:39 +0000 (0:00:00.024)       0:00:00.024 ***********
2026-06-08 13:09:40.260423 | controller | changed: [instance]
2026-06-08 13:09:40.260535 | controller |
2026-06-08 13:09:40.260563 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-06-08 13:09:40.260667 | controller | Monday 08 June 2026  13:09:40 +0000 (0:00:00.393)       0:00:00.417 ***********
2026-06-08 13:09:40.688293 | controller | changed: [instance]
2026-06-08 13:09:40.688396 | controller |
2026-06-08 13:09:40.688475 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-06-08 13:09:40.688569 | controller | Monday 08 June 2026  13:09:40 +0000 (0:00:00.427)       0:00:00.844 ***********
2026-06-08 13:09:41.225684 | controller | changed: [instance]
2026-06-08 13:09:41.225731 | controller |
2026-06-08 13:09:41.225832 | controller | TASK [Start mock iDRAC server] *************************************************
2026-06-08 13:09:41.225925 | controller | Monday 08 June 2026  13:09:41 +0000 (0:00:00.537)       0:00:01.382 ***********
2026-06-08 13:09:41.449645 | controller | changed: [instance]
2026-06-08 13:09:41.449734 | controller |
2026-06-08 13:09:41.449875 | controller | TASK [Record mock server PID] **************************************************
2026-06-08 13:09:41.450029 | controller | Monday 08 June 2026  13:09:41 +0000 (0:00:00.224)       0:00:01.606 ***********
2026-06-08 13:09:41.648842 | controller | ok: [instance]
2026-06-08 13:09:41.648898 | controller |
2026-06-08 13:09:41.649040 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-06-08 13:09:41.649106 | controller | Monday 08 June 2026  13:09:41 +0000 (0:00:00.199)       0:00:01.805 ***********
2026-06-08 13:09:42.143450 | controller | ok: [instance]
2026-06-08 13:09:42.143501 | controller |
2026-06-08 13:09:42.143592 | controller | PLAY RECAP *********************************************************************
2026-06-08 13:09:42.143703 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 13:09:42.143783 | controller |
2026-06-08 13:09:42.143864 | controller | Monday 08 June 2026  13:09:42 +0000 (0:00:00.494)       0:00:02.300 ***********
2026-06-08 13:09:42.143959 | controller | ===============================================================================
2026-06-08 13:09:42.144055 | controller | Copy mock iDRAC server script ------------------------------------------- 0.54s
2026-06-08 13:09:42.144148 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.50s
2026-06-08 13:09:42.144260 | controller | Generate self-signed TLS certificate ------------------------------------ 0.43s
2026-06-08 13:09:42.144349 | controller | Create mock server directory -------------------------------------------- 0.39s
2026-06-08 13:09:42.144436 | controller | Start mock iDRAC server ------------------------------------------------- 0.22s
2026-06-08 13:09:42.144525 | controller | Record mock server PID -------------------------------------------------- 0.20s
2026-06-08 13:09:42.219915 | controller | INFO     Running bm_redfish > converge
2026-06-08 13:09:42.736424 | controller |
2026-06-08 13:09:42.736486 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-06-08 13:09:42.736609 | controller |
2026-06-08 13:09:42.736679 | controller | TASK [Test bm_power_off] *******************************************************
2026-06-08 13:09:42.736771 | controller | Monday 08 June 2026  13:09:42 +0000 (0:00:00.060)       0:00:00.060 ***********
2026-06-08 13:09:42.762911 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_power_off.yml for instance
2026-06-08 13:09:42.762964 | controller |
2026-06-08 13:09:42.763026 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 13:09:42.763117 | controller | Monday 08 June 2026  13:09:42 +0000 (0:00:00.026)       0:00:00.087 ***********
2026-06-08 13:09:43.194467 | controller | ok: [instance]
2026-06-08 13:09:43.194528 | controller |
2026-06-08 13:09:43.194634 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 13:09:43.194731 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.431)       0:00:00.518 ***********
2026-06-08 13:09:43.229532 | controller |
2026-06-08 13:09:43.229611 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:43.229660 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.035)       0:00:00.553 ***********
2026-06-08 13:09:43.547054 | controller | ok: [instance]
2026-06-08 13:09:43.547102 | controller |
2026-06-08 13:09:43.547246 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 13:09:43.547390 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.317)       0:00:00.871 ***********
2026-06-08 13:09:43.567042 | controller | skipping: [instance]
2026-06-08 13:09:43.567186 | controller |
2026-06-08 13:09:43.567425 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 13:09:43.567636 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.020)       0:00:00.891 ***********
2026-06-08 13:09:43.593234 | controller | skipping: [instance]
2026-06-08 13:09:43.593289 | controller |
2026-06-08 13:09:43.593475 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-06-08 13:09:43.593595 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.026)       0:00:00.917 ***********
2026-06-08 13:09:43.911740 | controller | ok: [instance]
2026-06-08 13:09:43.912152 | controller |
2026-06-08 13:09:43.912187 | controller | TASK [Assert host is still Off] ************************************************
2026-06-08 13:09:43.912195 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.318)       0:00:01.236 ***********
2026-06-08 13:09:43.932475 | controller | ok: [instance] => {
2026-06-08 13:09:43.932516 | controller |     "changed": false,
2026-06-08 13:09:43.933101 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:43.933134 | controller | }
2026-06-08 13:09:43.933140 | controller |
2026-06-08 13:09:43.933146 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 13:09:43.933152 | controller | Monday 08 June 2026  13:09:43 +0000 (0:00:00.020)       0:00:01.256 ***********
2026-06-08 13:09:44.271049 | controller | ok: [instance]
2026-06-08 13:09:44.271078 | controller |
2026-06-08 13:09:44.271083 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 13:09:44.271088 | controller | Monday 08 June 2026  13:09:44 +0000 (0:00:00.338)       0:00:01.594 ***********
2026-06-08 13:09:44.303185 | controller |
2026-06-08 13:09:44.303218 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:44.303224 | controller | Monday 08 June 2026  13:09:44 +0000 (0:00:00.032)       0:00:01.626 ***********
2026-06-08 13:09:44.665004 | controller | ok: [instance]
2026-06-08 13:09:44.665036 | controller |
2026-06-08 13:09:44.665041 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 13:09:44.665045 | controller | Monday 08 June 2026  13:09:44 +0000 (0:00:00.362)       0:00:01.989 ***********
2026-06-08 13:09:45.010473 | controller | ok: [instance]
2026-06-08 13:09:45.010500 | controller |
2026-06-08 13:09:45.010505 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 13:09:45.010509 | controller | Monday 08 June 2026  13:09:45 +0000 (0:00:00.345)       0:00:02.334 ***********
2026-06-08 13:09:45.327203 | controller | ok: [instance]
2026-06-08 13:09:45.327234 | controller |
2026-06-08 13:09:45.327241 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-06-08 13:09:45.327254 | controller | Monday 08 June 2026  13:09:45 +0000 (0:00:00.316)       0:00:02.651 ***********
2026-06-08 13:09:45.658451 | controller | ok: [instance]
2026-06-08 13:09:45.658489 | controller |
2026-06-08 13:09:45.658496 | controller | TASK [Assert host is now Off] **************************************************
2026-06-08 13:09:45.658532 | controller | Monday 08 June 2026  13:09:45 +0000 (0:00:00.331)       0:00:02.982 ***********
2026-06-08 13:09:45.676478 | controller | ok: [instance] => {
2026-06-08 13:09:45.676515 | controller |     "changed": false,
2026-06-08 13:09:45.676520 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:45.676795 | controller | }
2026-06-08 13:09:45.676827 | controller |
2026-06-08 13:09:45.676832 | controller | TASK [Test bm_power_on] ********************************************************
2026-06-08 13:09:45.676837 | controller | Monday 08 June 2026  13:09:45 +0000 (0:00:00.018)       0:00:03.001 ***********
2026-06-08 13:09:45.699507 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_power_on.yml for instance
2026-06-08 13:09:45.699555 | controller |
2026-06-08 13:09:45.699563 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 13:09:45.699576 | controller | Monday 08 June 2026  13:09:45 +0000 (0:00:00.023)       0:00:03.024 ***********
2026-06-08 13:09:46.032477 | controller | ok: [instance]
2026-06-08 13:09:46.032506 | controller |
2026-06-08 13:09:46.032511 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 13:09:46.032541 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.332)       0:00:03.356 ***********
2026-06-08 13:09:46.058405 | controller |
2026-06-08 13:09:46.058438 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:46.058443 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.026)       0:00:03.383 ***********
2026-06-08 13:09:46.356273 | controller | ok: [instance]
2026-06-08 13:09:46.356300 | controller |
2026-06-08 13:09:46.356306 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 13:09:46.356322 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.297)       0:00:03.680 ***********
2026-06-08 13:09:46.377076 | controller | skipping: [instance]
2026-06-08 13:09:46.377106 | controller |
2026-06-08 13:09:46.377111 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 13:09:46.377116 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.020)       0:00:03.700 ***********
2026-06-08 13:09:46.734506 | controller | ok: [instance]
2026-06-08 13:09:46.734557 | controller |
2026-06-08 13:09:46.734565 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 13:09:46.734572 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.357)       0:00:04.058 ***********
2026-06-08 13:09:46.767484 | controller | ok: [instance] => {
2026-06-08 13:09:46.767567 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 13:09:46.767577 | controller | }
2026-06-08 13:09:46.767583 | controller |
2026-06-08 13:09:46.767588 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-06-08 13:09:46.767594 | controller | Monday 08 June 2026  13:09:46 +0000 (0:00:00.032)       0:00:04.091 ***********
2026-06-08 13:09:47.115049 | controller | ok: [instance]
2026-06-08 13:09:47.115077 | controller |
2026-06-08 13:09:47.115082 | controller | TASK [Assert host is still On with POST complete] ******************************
2026-06-08 13:09:47.115086 | controller | Monday 08 June 2026  13:09:47 +0000 (0:00:00.347)       0:00:04.439 ***********
2026-06-08 13:09:47.139473 | controller | ok: [instance] => {
2026-06-08 13:09:47.139513 | controller |     "changed": false,
2026-06-08 13:09:47.139518 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:47.139883 | controller | }
2026-06-08 13:09:47.139910 | controller |
2026-06-08 13:09:47.139914 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 13:09:47.139920 | controller | Monday 08 June 2026  13:09:47 +0000 (0:00:00.024)       0:00:04.463 ***********
2026-06-08 13:09:47.469442 | controller | ok: [instance]
2026-06-08 13:09:47.469481 | controller |
2026-06-08 13:09:47.469488 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 13:09:47.469523 | controller | Monday 08 June 2026  13:09:47 +0000 (0:00:00.329)       0:00:04.793 ***********
2026-06-08 13:09:47.500179 | controller |
2026-06-08 13:09:47.500217 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:47.500223 | controller | Monday 08 June 2026  13:09:47 +0000 (0:00:00.030)       0:00:04.824 ***********
2026-06-08 13:09:47.901193 | controller | ok: [instance]
2026-06-08 13:09:47.901228 | controller |
2026-06-08 13:09:47.901235 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 13:09:47.901242 | controller | Monday 08 June 2026  13:09:47 +0000 (0:00:00.400)       0:00:05.225 ***********
2026-06-08 13:09:48.225410 | controller | ok: [instance]
2026-06-08 13:09:48.225434 | controller |
2026-06-08 13:09:48.225440 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 13:09:48.225444 | controller | Monday 08 June 2026  13:09:48 +0000 (0:00:00.324)       0:00:05.549 ***********
2026-06-08 13:09:48.605374 | controller | ok: [instance]
2026-06-08 13:09:48.605407 | controller |
2026-06-08 13:09:48.605413 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 13:09:48.605419 | controller | Monday 08 June 2026  13:09:48 +0000 (0:00:00.379)       0:00:05.929 ***********
2026-06-08 13:09:48.666551 | controller | ok: [instance] => {
2026-06-08 13:09:48.666605 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 13:09:48.666613 | controller | }
2026-06-08 13:09:48.667299 | controller |
2026-06-08 13:09:48.667382 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-06-08 13:09:48.667393 | controller | Monday 08 June 2026  13:09:48 +0000 (0:00:00.060)       0:00:05.989 ***********
2026-06-08 13:09:48.974490 | controller | ok: [instance]
2026-06-08 13:09:48.974567 | controller |
2026-06-08 13:09:48.974576 | controller | TASK [Assert host is now On with POST complete] ********************************
2026-06-08 13:09:48.974582 | controller | Monday 08 June 2026  13:09:48 +0000 (0:00:00.308)       0:00:06.298 ***********
2026-06-08 13:09:48.999340 | controller | ok: [instance] => {
2026-06-08 13:09:48.999378 | controller |     "changed": false,
2026-06-08 13:09:48.999385 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:48.999392 | controller | }
2026-06-08 13:09:48.999397 | controller |
2026-06-08 13:09:48.999403 | controller | TASK [Reset mock to power Off without PostState support] ***********************
2026-06-08 13:09:48.999409 | controller | Monday 08 June 2026  13:09:48 +0000 (0:00:00.024)       0:00:06.322 ***********
2026-06-08 13:09:49.337068 | controller | ok: [instance]
2026-06-08 13:09:49.337096 | controller |
2026-06-08 13:09:49.337101 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 13:09:49.337105 | controller | Monday 08 June 2026  13:09:49 +0000 (0:00:00.338)       0:00:06.661 ***********
2026-06-08 13:09:49.361448 | controller |
2026-06-08 13:09:49.361487 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:49.361493 | controller | Monday 08 June 2026  13:09:49 +0000 (0:00:00.024)       0:00:06.685 ***********
2026-06-08 13:09:49.725164 | controller | ok: [instance]
2026-06-08 13:09:49.725193 | controller |
2026-06-08 13:09:49.725204 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 13:09:49.725209 | controller | Monday 08 June 2026  13:09:49 +0000 (0:00:00.363)       0:00:07.049 ***********
2026-06-08 13:09:50.071612 | controller | ok: [instance]
2026-06-08 13:09:50.071670 | controller |
2026-06-08 13:09:50.071675 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 13:09:50.071681 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.346)       0:00:07.395 ***********
2026-06-08 13:09:50.414333 | controller | ok: [instance]
2026-06-08 13:09:50.414360 | controller |
2026-06-08 13:09:50.414365 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 13:09:50.414370 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.342)       0:00:07.738 ***********
2026-06-08 13:09:50.455613 | controller | ok: [instance] => {
2026-06-08 13:09:50.455682 | controller |     "msg": "POST state: not supported by firmware, used PowerState=On"
2026-06-08 13:09:50.455694 | controller | }
2026-06-08 13:09:50.455703 | controller |
2026-06-08 13:09:50.455805 | controller | TASK [Query mock state after power_on (no PostState)] **************************
2026-06-08 13:09:50.455850 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.041)       0:00:07.779 ***********
2026-06-08 13:09:50.789978 | controller | ok: [instance]
2026-06-08 13:09:50.790006 | controller |
2026-06-08 13:09:50.790011 | controller | TASK [Assert host is On (PostState stays null)] ********************************
2026-06-08 13:09:50.790016 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.334)       0:00:08.114 ***********
2026-06-08 13:09:50.814284 | controller | ok: [instance] => {
2026-06-08 13:09:50.814334 | controller |     "changed": false,
2026-06-08 13:09:50.814340 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:50.814346 | controller | }
2026-06-08 13:09:50.814361 | controller |
2026-06-08 13:09:50.814366 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-06-08 13:09:50.814371 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.024)       0:00:08.138 ***********
2026-06-08 13:09:50.842778 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_check_usb_boot.yml for instance
2026-06-08 13:09:50.842810 | controller |
2026-06-08 13:09:50.842867 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-06-08 13:09:50.842875 | controller | Monday 08 June 2026  13:09:50 +0000 (0:00:00.028)       0:00:08.166 ***********
2026-06-08 13:09:51.165877 | controller | ok: [instance]
2026-06-08 13:09:51.165908 | controller |
2026-06-08 13:09:51.165913 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-06-08 13:09:51.165917 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.323)       0:00:08.490 ***********
2026-06-08 13:09:51.204221 | controller |
2026-06-08 13:09:51.204273 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 13:09:51.204282 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.037)       0:00:08.527 ***********
2026-06-08 13:09:51.576520 | controller | ok: [instance]
2026-06-08 13:09:51.576589 | controller |
2026-06-08 13:09:51.577003 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 13:09:51.577027 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.372)       0:00:08.899 ***********
2026-06-08 13:09:51.615200 | controller | ok: [instance]
2026-06-08 13:09:51.615240 | controller |
2026-06-08 13:09:51.615246 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 13:09:51.615251 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.039)       0:00:08.938 ***********
2026-06-08 13:09:51.652585 | controller | skipping: [instance]
2026-06-08 13:09:51.652631 | controller |
2026-06-08 13:09:51.652833 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-06-08 13:09:51.652886 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.037)       0:00:08.976 ***********
2026-06-08 13:09:51.686177 | controller | ok: [instance] => {
2026-06-08 13:09:51.686414 | controller |     "changed": false,
2026-06-08 13:09:51.686577 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:51.686705 | controller | }
2026-06-08 13:09:51.686853 | controller |
2026-06-08 13:09:51.687014 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 13:09:51.687173 | controller | Monday 08 June 2026  13:09:51 +0000 (0:00:00.034)       0:00:09.010 ***********
2026-06-08 13:09:52.050408 | controller | ok: [instance]
2026-06-08 13:09:52.050436 | controller |
2026-06-08 13:09:52.050441 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-06-08 13:09:52.050446 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.364)       0:00:09.374 ***********
2026-06-08 13:09:52.073945 | controller |
2026-06-08 13:09:52.073975 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 13:09:52.073980 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.023)       0:00:09.398 ***********
2026-06-08 13:09:52.407079 | controller | ok: [instance]
2026-06-08 13:09:52.407111 | controller |
2026-06-08 13:09:52.407116 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 13:09:52.407121 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.332)       0:00:09.731 ***********
2026-06-08 13:09:52.439370 | controller | ok: [instance]
2026-06-08 13:09:52.439403 | controller |
2026-06-08 13:09:52.439409 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 13:09:52.439414 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.032)       0:00:09.763 ***********
2026-06-08 13:09:52.466289 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 13:09:52.471006 | controller |
2026-06-08 13:09:52.471020 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-06-08 13:09:52.471025 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.032)       0:00:09.795 ***********
2026-06-08 13:09:52.492454 | controller | ok: [instance] => {
2026-06-08 13:09:52.492490 | controller |     "changed": false,
2026-06-08 13:09:52.492496 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:52.492818 | controller | }
2026-06-08 13:09:52.492829 | controller |
2026-06-08 13:09:52.492833 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-06-08 13:09:52.492838 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.020)       0:00:09.816 ***********
2026-06-08 13:09:52.532109 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_ensure_usb_boot.yml for instance
2026-06-08 13:09:52.532308 | controller |
2026-06-08 13:09:52.532525 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-06-08 13:09:52.532682 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.039)       0:00:09.856 ***********
2026-06-08 13:09:52.855249 | controller | ok: [instance]
2026-06-08 13:09:52.855275 | controller |
2026-06-08 13:09:52.855285 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-06-08 13:09:52.855290 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.322)       0:00:10.179 ***********
2026-06-08 13:09:52.883972 | controller |
2026-06-08 13:09:52.883998 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 13:09:52.884003 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.028)       0:00:10.208 ***********
2026-06-08 13:09:52.905404 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_check_usb_boot.yml for instance
2026-06-08 13:09:52.905420 | controller |
2026-06-08 13:09:52.905425 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 13:09:52.905488 | controller | Monday 08 June 2026  13:09:52 +0000 (0:00:00.021)       0:00:10.229 ***********
2026-06-08 13:09:53.222272 | controller | ok: [instance]
2026-06-08 13:09:53.222299 | controller |
2026-06-08 13:09:53.222304 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 13:09:53.222377 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.316)       0:00:10.546 ***********
2026-06-08 13:09:53.254197 | controller | ok: [instance]
2026-06-08 13:09:53.254228 | controller |
2026-06-08 13:09:53.254233 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 13:09:53.254237 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.031)       0:00:10.578 ***********
2026-06-08 13:09:53.285666 | controller | skipping: [instance]
2026-06-08 13:09:53.285716 | controller |
2026-06-08 13:09:53.285722 | controller | TASK [Query mock state] ********************************************************
2026-06-08 13:09:53.285732 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.031)       0:00:10.609 ***********
2026-06-08 13:09:53.602949 | controller | ok: [instance]
2026-06-08 13:09:53.602980 | controller |
2026-06-08 13:09:53.602985 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-06-08 13:09:53.602990 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.317)       0:00:10.927 ***********
2026-06-08 13:09:53.626543 | controller | ok: [instance] => {
2026-06-08 13:09:53.626592 | controller |     "changed": false,
2026-06-08 13:09:53.626598 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:53.626604 | controller | }
2026-06-08 13:09:53.626610 | controller |
2026-06-08 13:09:53.626615 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-06-08 13:09:53.626620 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.023)       0:00:10.950 ***********
2026-06-08 13:09:53.974499 | controller | ok: [instance]
2026-06-08 13:09:53.974549 | controller |
2026-06-08 13:09:53.974560 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-06-08 13:09:53.974567 | controller | Monday 08 June 2026  13:09:53 +0000 (0:00:00.348)       0:00:11.298 ***********
2026-06-08 13:09:54.009052 | controller |
2026-06-08 13:09:54.009084 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 13:09:54.009090 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.034)       0:00:11.333 ***********
2026-06-08 13:09:54.029287 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_check_usb_boot.yml for instance
2026-06-08 13:09:54.029342 | controller |
2026-06-08 13:09:54.029351 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 13:09:54.029357 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.020)       0:00:11.353 ***********
2026-06-08 13:09:54.436164 | controller | ok: [instance]
2026-06-08 13:09:54.436201 | controller |
2026-06-08 13:09:54.436207 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 13:09:54.436212 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.406)       0:00:11.760 ***********
2026-06-08 13:09:54.476541 | controller | ok: [instance]
2026-06-08 13:09:54.476594 | controller |
2026-06-08 13:09:54.476602 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 13:09:54.476609 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.040)       0:00:11.800 ***********
2026-06-08 13:09:54.507567 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 13:09:54.512653 | controller |
2026-06-08 13:09:54.512677 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 13:09:54.512684 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.036)       0:00:11.837 ***********
2026-06-08 13:09:54.544509 | controller | skipping: [instance]
2026-06-08 13:09:54.544562 | controller |
2026-06-08 13:09:54.544569 | controller | TASK [bm_sno : Set GenericUsbBoot BIOS attribute] ******************************
2026-06-08 13:09:54.544575 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.031)       0:00:11.868 ***********
2026-06-08 13:09:54.893113 | controller | ok: [instance]
2026-06-08 13:09:54.893158 | controller |
2026-06-08 13:09:54.893165 | controller | TASK [bm_sno : Create BIOS config job to schedule the change] ******************
2026-06-08 13:09:54.893170 | controller | Monday 08 June 2026  13:09:54 +0000 (0:00:00.348)       0:00:12.216 ***********
2026-06-08 13:09:55.236557 | controller | ok: [instance]
2026-06-08 13:09:55.236602 | controller |
2026-06-08 13:09:55.236608 | controller | TASK [bm_sno : Power off before applying BIOS change] **************************
2026-06-08 13:09:55.236612 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.343)       0:00:12.560 ***********
2026-06-08 13:09:55.260459 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_power_off.yml for instance
2026-06-08 13:09:55.260505 | controller |
2026-06-08 13:09:55.260511 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:55.260516 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.023)       0:00:12.584 ***********
2026-06-08 13:09:55.589999 | controller | ok: [instance]
2026-06-08 13:09:55.590056 | controller |
2026-06-08 13:09:55.590089 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 13:09:55.590098 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.329)       0:00:12.913 ***********
2026-06-08 13:09:55.606273 | controller | skipping: [instance]
2026-06-08 13:09:55.606350 | controller |
2026-06-08 13:09:55.606358 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 13:09:55.606366 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.016)       0:00:12.930 ***********
2026-06-08 13:09:55.625047 | controller | skipping: [instance]
2026-06-08 13:09:55.625280 | controller |
2026-06-08 13:09:55.625479 | controller | TASK [bm_sno : Power on to apply BIOS config job during POST] ******************
2026-06-08 13:09:55.625616 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.018)       0:00:12.948 ***********
2026-06-08 13:09:55.655382 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_power_on.yml for instance
2026-06-08 13:09:55.655618 | controller |
2026-06-08 13:09:55.655824 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:55.656010 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.030)       0:00:12.979 ***********
2026-06-08 13:09:55.997263 | controller | ok: [instance]
2026-06-08 13:09:55.997553 | controller |
2026-06-08 13:09:55.997744 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 13:09:55.997916 | controller | Monday 08 June 2026  13:09:55 +0000 (0:00:00.341)       0:00:13.321 ***********
2026-06-08 13:09:56.351479 | controller | ok: [instance]
2026-06-08 13:09:56.351512 | controller |
2026-06-08 13:09:56.351517 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 13:09:56.351525 | controller | Monday 08 June 2026  13:09:56 +0000 (0:00:00.354)       0:00:13.675 ***********
2026-06-08 13:09:56.723850 | controller | ok: [instance]
2026-06-08 13:09:56.723879 | controller |
2026-06-08 13:09:56.723884 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 13:09:56.723889 | controller | Monday 08 June 2026  13:09:56 +0000 (0:00:00.372)       0:00:14.048 ***********
2026-06-08 13:09:56.756486 | controller | ok: [instance] => {
2026-06-08 13:09:56.756518 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 13:09:56.757023 | controller | }
2026-06-08 13:09:56.757058 | controller |
2026-06-08 13:09:56.757064 | controller | TASK [bm_sno : Power off after BIOS change applied] ****************************
2026-06-08 13:09:56.757070 | controller | Monday 08 June 2026  13:09:56 +0000 (0:00:00.032)       0:00:14.080 ***********
2026-06-08 13:09:56.787897 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_power_off.yml for instance
2026-06-08 13:09:56.787924 | controller |
2026-06-08 13:09:56.787929 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 13:09:56.787933 | controller | Monday 08 June 2026  13:09:56 +0000 (0:00:00.031)       0:00:14.112 ***********
2026-06-08 13:09:57.086977 | controller | ok: [instance]
2026-06-08 13:09:57.087011 | controller |
2026-06-08 13:09:57.087018 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 13:09:57.087024 | controller | Monday 08 June 2026  13:09:57 +0000 (0:00:00.299)       0:00:14.411 ***********
2026-06-08 13:09:57.443529 | controller | ok: [instance]
2026-06-08 13:09:57.443566 | controller |
2026-06-08 13:09:57.443572 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 13:09:57.443578 | controller | Monday 08 June 2026  13:09:57 +0000 (0:00:00.356)       0:00:14.767 ***********
2026-06-08 13:09:57.867224 | controller | ok: [instance]
2026-06-08 13:09:57.867262 | controller |
2026-06-08 13:09:57.867268 | controller | TASK [Query mock state after auto-enable] **************************************
2026-06-08 13:09:57.867274 | controller | Monday 08 June 2026  13:09:57 +0000 (0:00:00.423)       0:00:15.191 ***********
2026-06-08 13:09:58.240627 | controller | ok: [instance]
2026-06-08 13:09:58.240687 | controller |
2026-06-08 13:09:58.240692 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-06-08 13:09:58.240698 | controller | Monday 08 June 2026  13:09:58 +0000 (0:00:00.373)       0:00:15.564 ***********
2026-06-08 13:09:58.268516 | controller | ok: [instance] => {
2026-06-08 13:09:58.268558 | controller |     "changed": false,
2026-06-08 13:09:58.268565 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:58.268572 | controller | }
2026-06-08 13:09:58.268578 | controller |
2026-06-08 13:09:58.268584 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 13:09:58.268593 | controller | Monday 08 June 2026  13:09:58 +0000 (0:00:00.027)       0:00:15.592 ***********
2026-06-08 13:09:58.668215 | controller | ok: [instance]
2026-06-08 13:09:58.668267 | controller |
2026-06-08 13:09:58.668274 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-06-08 13:09:58.668281 | controller | Monday 08 June 2026  13:09:58 +0000 (0:00:00.399)       0:00:15.991 ***********
2026-06-08 13:09:58.701927 | controller |
2026-06-08 13:09:58.701978 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 13:09:58.701986 | controller | Monday 08 June 2026  13:09:58 +0000 (0:00:00.033)       0:00:16.025 ***********
2026-06-08 13:09:58.722383 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/tasks/bm_check_usb_boot.yml for instance
2026-06-08 13:09:58.722422 | controller |
2026-06-08 13:09:58.722429 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 13:09:58.722451 | controller | Monday 08 June 2026  13:09:58 +0000 (0:00:00.020)       0:00:16.046 ***********
2026-06-08 13:09:59.071409 | controller | ok: [instance]
2026-06-08 13:09:59.071445 | controller |
2026-06-08 13:09:59.071468 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 13:09:59.071474 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.348)       0:00:16.395 ***********
2026-06-08 13:09:59.106961 | controller | ok: [instance]
2026-06-08 13:09:59.107000 | controller |
2026-06-08 13:09:59.107008 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 13:09:59.107014 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.035)       0:00:16.430 ***********
2026-06-08 13:09:59.135290 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 13:09:59.144945 | controller |
2026-06-08 13:09:59.144980 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 13:09:59.144986 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.037)       0:00:16.468 ***********
2026-06-08 13:09:59.191078 | 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-06-08 13:09:59.195986 | controller |
2026-06-08 13:09:59.196183 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-06-08 13:09:59.196409 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.052)       0:00:16.520 ***********
2026-06-08 13:09:59.222307 | controller | ok: [instance] => {
2026-06-08 13:09:59.222598 | controller |     "changed": false,
2026-06-08 13:09:59.222771 | controller |     "msg": "All assertions passed"
2026-06-08 13:09:59.222931 | controller | }
2026-06-08 13:09:59.223083 | controller |
2026-06-08 13:09:59.223251 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-06-08 13:09:59.223437 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.025)       0:00:16.546 ***********
2026-06-08 13:09:59.274416 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_eject_vmedia.yml for instance
2026-06-08 13:09:59.274618 | controller |
2026-06-08 13:09:59.274749 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 13:09:59.274875 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.052)       0:00:16.598 ***********
2026-06-08 13:09:59.624775 | controller | ok: [instance]
2026-06-08 13:09:59.624806 | controller |
2026-06-08 13:09:59.624812 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-06-08 13:09:59.624816 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.350)       0:00:16.948 ***********
2026-06-08 13:09:59.654486 | controller |
2026-06-08 13:09:59.654760 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 13:09:59.654775 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.029)       0:00:16.978 ***********
2026-06-08 13:09:59.968214 | controller | ok: [instance]
2026-06-08 13:09:59.968252 | controller |
2026-06-08 13:09:59.968259 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 13:09:59.968266 | controller | Monday 08 June 2026  13:09:59 +0000 (0:00:00.312)       0:00:17.291 ***********
2026-06-08 13:10:05.000232 | controller | Pausing for 5 seconds
2026-06-08 13:10:05.000306 | controller | ok: [instance]
2026-06-08 13:10:05.000344 | controller |
2026-06-08 13:10:05.000350 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 13:10:05.000355 | controller | Monday 08 June 2026  13:10:04 +0000 (0:00:05.031)       0:00:22.323 ***********
2026-06-08 13:10:05.308420 | controller | ok: [instance]
2026-06-08 13:10:05.308483 | controller |
2026-06-08 13:10:05.308610 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 13:10:05.308640 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.309)       0:00:22.632 ***********
2026-06-08 13:10:05.347150 | controller | ok: [instance] => {
2026-06-08 13:10:05.347179 | controller |     "msg": ""
2026-06-08 13:10:05.347184 | controller | }
2026-06-08 13:10:05.347188 | controller |
2026-06-08 13:10:05.347192 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 13:10:05.347197 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.038)       0:00:22.670 ***********
2026-06-08 13:10:05.377600 | controller | skipping: [instance]
2026-06-08 13:10:05.377652 | controller |
2026-06-08 13:10:05.377663 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 13:10:05.377672 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.030)       0:00:22.701 ***********
2026-06-08 13:10:05.409924 | controller | skipping: [instance]
2026-06-08 13:10:05.409961 | controller |
2026-06-08 13:10:05.409967 | controller | TASK [Query mock state after eject] ********************************************
2026-06-08 13:10:05.409973 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.032)       0:00:22.734 ***********
2026-06-08 13:10:05.728531 | controller | ok: [instance]
2026-06-08 13:10:05.728581 | controller |
2026-06-08 13:10:05.728757 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-06-08 13:10:05.728788 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.318)       0:00:23.052 ***********
2026-06-08 13:10:05.759349 | controller | ok: [instance] => {
2026-06-08 13:10:05.759379 | controller |     "changed": false,
2026-06-08 13:10:05.759383 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:05.759388 | controller | }
2026-06-08 13:10:05.759392 | controller |
2026-06-08 13:10:05.759396 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-06-08 13:10:05.759400 | controller | Monday 08 June 2026  13:10:05 +0000 (0:00:00.030)       0:00:23.083 ***********
2026-06-08 13:10:06.071534 | controller | ok: [instance]
2026-06-08 13:10:06.071583 | controller |
2026-06-08 13:10:06.071596 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-06-08 13:10:06.071606 | controller | Monday 08 June 2026  13:10:06 +0000 (0:00:00.312)       0:00:23.395 ***********
2026-06-08 13:10:06.098881 | controller |
2026-06-08 13:10:06.098918 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 13:10:06.098925 | controller | Monday 08 June 2026  13:10:06 +0000 (0:00:00.027)       0:00:23.422 ***********
2026-06-08 13:10:06.400886 | controller | ok: [instance]
2026-06-08 13:10:06.400919 | controller |
2026-06-08 13:10:06.400926 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 13:10:06.400937 | controller | Monday 08 June 2026  13:10:06 +0000 (0:00:00.302)       0:00:23.725 ***********
2026-06-08 13:10:11.424406 | controller | Pausing for 5 seconds
2026-06-08 13:10:11.424439 | controller | ok: [instance]
2026-06-08 13:10:11.424444 | controller |
2026-06-08 13:10:11.424448 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 13:10:11.424479 | controller | Monday 08 June 2026  13:10:11 +0000 (0:00:05.023)       0:00:28.748 ***********
2026-06-08 13:10:11.633920 | controller | ok: [instance]
2026-06-08 13:10:11.633949 | controller |
2026-06-08 13:10:11.633954 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 13:10:11.633959 | controller | Monday 08 June 2026  13:10:11 +0000 (0:00:00.209)       0:00:28.958 ***********
2026-06-08 13:10:11.664493 | controller | ok: [instance] => {
2026-06-08 13:10:11.664535 | controller |     "msg": ""
2026-06-08 13:10:11.664973 | controller | }
2026-06-08 13:10:11.665007 | controller |
2026-06-08 13:10:11.665013 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 13:10:11.665019 | controller | Monday 08 June 2026  13:10:11 +0000 (0:00:00.030)       0:00:28.988 ***********
2026-06-08 13:10:11.695781 | controller | skipping: [instance]
2026-06-08 13:10:11.695812 | controller |
2026-06-08 13:10:11.695817 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 13:10:11.695823 | controller | Monday 08 June 2026  13:10:11 +0000 (0:00:00.031)       0:00:29.020 ***********
2026-06-08 13:10:11.730071 | controller | skipping: [instance]
2026-06-08 13:10:11.730106 | controller |
2026-06-08 13:10:11.730112 | controller | TASK [Query mock state] ********************************************************
2026-06-08 13:10:11.730118 | controller | Monday 08 June 2026  13:10:11 +0000 (0:00:00.034)       0:00:29.054 ***********
2026-06-08 13:10:12.068019 | controller | ok: [instance]
2026-06-08 13:10:12.068049 | controller |
2026-06-08 13:10:12.068054 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-06-08 13:10:12.068058 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.338)       0:00:29.392 ***********
2026-06-08 13:10:12.097137 | controller | ok: [instance] => {
2026-06-08 13:10:12.097369 | controller |     "changed": false,
2026-06-08 13:10:12.097505 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:12.097640 | controller | }
2026-06-08 13:10:12.097757 | controller |
2026-06-08 13:10:12.097880 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-06-08 13:10:12.098001 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.029)       0:00:29.421 ***********
2026-06-08 13:10:12.158272 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno/molecule/bm_redfish/tasks/test_discover_vmedia.yml for instance
2026-06-08 13:10:12.158442 | controller |
2026-06-08 13:10:12.158598 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 13:10:12.158726 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.061)       0:00:29.482 ***********
2026-06-08 13:10:12.173114 | controller | ok: [instance]
2026-06-08 13:10:12.173294 | controller |
2026-06-08 13:10:12.173476 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 13:10:12.173609 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.014)       0:00:29.497 ***********
2026-06-08 13:10:12.494460 | controller | ok: [instance]
2026-06-08 13:10:12.494490 | controller |
2026-06-08 13:10:12.494495 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-06-08 13:10:12.494500 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.320)       0:00:29.818 ***********
2026-06-08 13:10:12.531024 | controller |
2026-06-08 13:10:12.531063 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 13:10:12.531071 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.036)       0:00:29.855 ***********
2026-06-08 13:10:12.862254 | controller | ok: [instance]
2026-06-08 13:10:12.862290 | controller |
2026-06-08 13:10:12.862297 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 13:10:12.862303 | controller | Monday 08 June 2026  13:10:12 +0000 (0:00:00.330)       0:00:30.186 ***********
2026-06-08 13:10:14.445484 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:14.445564 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:14.445569 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:14.445572 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:14.445576 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:14.445579 | controller | ok: [instance]
2026-06-08 13:10:14.445583 | controller |
2026-06-08 13:10:14.445587 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 13:10:14.445591 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:01.582)       0:00:31.768 ***********
2026-06-08 13:10:14.487548 | controller | ok: [instance]
2026-06-08 13:10:14.487590 | controller |
2026-06-08 13:10:14.487595 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 13:10:14.487600 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.042)       0:00:31.811 ***********
2026-06-08 13:10:14.538555 | controller | ok: [instance] => {
2026-06-08 13:10:14.538598 | controller |     "msg": [
2026-06-08 13:10:14.538605 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 13:10:14.538642 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 13:10:14.538651 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 13:10:14.538656 | controller |         "Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi",
2026-06-08 13:10:14.538662 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:10:14.538667 | controller |     ]
2026-06-08 13:10:14.538672 | controller | }
2026-06-08 13:10:14.538677 | controller |
2026-06-08 13:10:14.538682 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 13:10:14.538693 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.050)       0:00:31.861 ***********
2026-06-08 13:10:14.575120 | controller | skipping: [instance]
2026-06-08 13:10:14.575219 | controller |
2026-06-08 13:10:14.575457 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 13:10:14.575575 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.037)       0:00:31.899 ***********
2026-06-08 13:10:14.654282 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:14.654452 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:14.654616 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:14.654766 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:14.654951 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:14.655096 | controller |
2026-06-08 13:10:14.655275 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 13:10:14.655509 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.079)       0:00:31.978 ***********
2026-06-08 13:10:14.716817 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:14.716922 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:14.717044 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:14.717210 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:14.717332 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:14.717522 | controller | skipping: [instance]
2026-06-08 13:10:14.717675 | controller |
2026-06-08 13:10:14.717802 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 13:10:14.717955 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.062)       0:00:32.041 ***********
2026-06-08 13:10:14.778075 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:14.778171 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:14.778280 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:14.778428 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:14.778543 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:14.778640 | controller | skipping: [instance]
2026-06-08 13:10:14.778740 | controller |
2026-06-08 13:10:14.778857 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 13:10:14.778957 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.060)       0:00:32.102 ***********
2026-06-08 13:10:14.807741 | controller | skipping: [instance]
2026-06-08 13:10:14.807837 | controller |
2026-06-08 13:10:14.807950 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 13:10:14.808070 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.029)       0:00:32.132 ***********
2026-06-08 13:10:14.825512 | controller | ok: [instance] => {
2026-06-08 13:10:14.825654 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:14.825792 | controller | }
2026-06-08 13:10:14.825960 | controller |
2026-06-08 13:10:14.826106 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 13:10:14.826222 | controller | Monday 08 June 2026  13:10:14 +0000 (0:00:00.018)       0:00:32.150 ***********
2026-06-08 13:10:15.181385 | controller | ok: [instance]
2026-06-08 13:10:15.181426 | controller |
2026-06-08 13:10:15.181433 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 13:10:15.181438 | controller | Monday 08 June 2026  13:10:15 +0000 (0:00:00.355)       0:00:32.505 ***********
2026-06-08 13:10:25.225056 | controller | Pausing for 10 seconds
2026-06-08 13:10:25.225089 | controller | ok: [instance]
2026-06-08 13:10:25.225095 | controller |
2026-06-08 13:10:25.225100 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 13:10:25.225106 | controller | Monday 08 June 2026  13:10:25 +0000 (0:00:10.043)       0:00:42.549 ***********
2026-06-08 13:10:25.563078 | controller | ok: [instance]
2026-06-08 13:10:25.563115 | controller |
2026-06-08 13:10:25.563122 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 13:10:25.563128 | controller | Monday 08 June 2026  13:10:25 +0000 (0:00:00.338)       0:00:42.887 ***********
2026-06-08 13:10:25.939520 | controller | ok: [instance]
2026-06-08 13:10:25.939583 | controller |
2026-06-08 13:10:25.939589 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 13:10:25.939635 | controller | Monday 08 June 2026  13:10:25 +0000 (0:00:00.375)       0:00:43.263 ***********
2026-06-08 13:10:25.989007 | controller | ok: [instance] => {
2026-06-08 13:10:25.989054 | controller |     "changed": false,
2026-06-08 13:10:25.989074 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:25.989079 | controller | }
2026-06-08 13:10:25.989084 | controller |
2026-06-08 13:10:25.989088 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 13:10:25.989093 | controller | Monday 08 June 2026  13:10:25 +0000 (0:00:00.049)       0:00:43.312 ***********
2026-06-08 13:10:26.009577 | controller | ok: [instance] => {
2026-06-08 13:10:26.009621 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:26.009626 | controller | }
2026-06-08 13:10:26.010012 | controller |
2026-06-08 13:10:26.010062 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 13:10:26.010072 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.021)       0:00:43.333 ***********
2026-06-08 13:10:26.428020 | controller | ok: [instance]
2026-06-08 13:10:26.428068 | controller |
2026-06-08 13:10:26.428074 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 13:10:26.428079 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.418)       0:00:43.751 ***********
2026-06-08 13:10:26.470540 | controller | ok: [instance] => {
2026-06-08 13:10:26.470597 | controller |     "changed": false,
2026-06-08 13:10:26.470608 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:26.470618 | controller | }
2026-06-08 13:10:26.470626 | controller |
2026-06-08 13:10:26.470837 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-06-08 13:10:26.470888 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.042)       0:00:43.793 ***********
2026-06-08 13:10:26.520567 | controller | ok: [instance] => {
2026-06-08 13:10:26.520624 | controller |     "changed": false,
2026-06-08 13:10:26.520629 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:26.521062 | controller | }
2026-06-08 13:10:26.521110 | controller |
2026-06-08 13:10:26.521117 | controller | TASK [Query mock state after discover] *****************************************
2026-06-08 13:10:26.521124 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.050)       0:00:43.844 ***********
2026-06-08 13:10:26.884132 | controller | ok: [instance]
2026-06-08 13:10:26.884168 | controller |
2026-06-08 13:10:26.884175 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 13:10:26.884181 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.363)       0:00:44.208 ***********
2026-06-08 13:10:26.913104 | controller | ok: [instance] => {
2026-06-08 13:10:26.913139 | controller |     "changed": false,
2026-06-08 13:10:26.913145 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:26.913149 | controller | }
2026-06-08 13:10:26.913153 | controller |
2026-06-08 13:10:26.913157 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 13:10:26.913161 | controller | Monday 08 June 2026  13:10:26 +0000 (0:00:00.028)       0:00:44.237 ***********
2026-06-08 13:10:27.285212 | controller | ok: [instance]
2026-06-08 13:10:27.285263 | controller |
2026-06-08 13:10:27.285276 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-06-08 13:10:27.285283 | controller | Monday 08 June 2026  13:10:27 +0000 (0:00:00.371)       0:00:44.609 ***********
2026-06-08 13:10:27.321106 | controller |
2026-06-08 13:10:27.321150 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 13:10:27.321156 | controller | Monday 08 June 2026  13:10:27 +0000 (0:00:00.036)       0:00:44.645 ***********
2026-06-08 13:10:27.682798 | controller | ok: [instance]
2026-06-08 13:10:27.682957 | controller |
2026-06-08 13:10:27.683091 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 13:10:27.683236 | controller | Monday 08 June 2026  13:10:27 +0000 (0:00:00.362)       0:00:45.007 ***********
2026-06-08 13:10:29.442499 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:29.442553 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:29.443208 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:29.443236 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:29.443241 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:29.443245 | controller | ok: [instance]
2026-06-08 13:10:29.443249 | controller |
2026-06-08 13:10:29.443253 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 13:10:29.443258 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:01.759)       0:00:46.766 ***********
2026-06-08 13:10:29.480822 | controller | ok: [instance]
2026-06-08 13:10:29.480855 | controller |
2026-06-08 13:10:29.480860 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 13:10:29.480864 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.038)       0:00:46.804 ***********
2026-06-08 13:10:29.519570 | controller | ok: [instance] => {
2026-06-08 13:10:29.519610 | controller |     "msg": [
2026-06-08 13:10:29.519617 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 13:10:29.519621 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 13:10:29.519625 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 13:10:29.520254 | controller |         "Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi",
2026-06-08 13:10:29.520281 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:10:29.520287 | controller |     ]
2026-06-08 13:10:29.520291 | controller | }
2026-06-08 13:10:29.520295 | controller |
2026-06-08 13:10:29.520299 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 13:10:29.520303 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.038)       0:00:46.843 ***********
2026-06-08 13:10:29.559143 | controller | ok: [instance] => {
2026-06-08 13:10:29.559308 | controller |     "changed": false,
2026-06-08 13:10:29.559524 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:29.559654 | controller | }
2026-06-08 13:10:29.559773 | controller |
2026-06-08 13:10:29.559900 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 13:10:29.560036 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.039)       0:00:46.883 ***********
2026-06-08 13:10:29.622490 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:29.622620 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:29.622628 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:29.622787 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:29.622915 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:29.623016 | controller | skipping: [instance]
2026-06-08 13:10:29.623119 | controller |
2026-06-08 13:10:29.623216 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 13:10:29.623361 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.063)       0:00:46.946 ***********
2026-06-08 13:10:29.681424 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:29.681512 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:29.681639 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:29.681797 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:29.681892 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:29.681995 | controller | skipping: [instance]
2026-06-08 13:10:29.682087 | controller |
2026-06-08 13:10:29.682241 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 13:10:29.682360 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.058)       0:00:47.005 ***********
2026-06-08 13:10:29.737972 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:29.738058 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:29.738247 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 13:10:29.738402 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:29.738508 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:29.738635 | controller | skipping: [instance]
2026-06-08 13:10:29.738776 | controller |
2026-06-08 13:10:29.738907 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 13:10:29.739049 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.056)       0:00:47.062 ***********
2026-06-08 13:10:29.768090 | controller | skipping: [instance]
2026-06-08 13:10:29.768213 | controller |
2026-06-08 13:10:29.768370 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 13:10:29.768522 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.030)       0:00:47.092 ***********
2026-06-08 13:10:29.788327 | controller | ok: [instance] => {
2026-06-08 13:10:29.788425 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:29.788568 | controller | }
2026-06-08 13:10:29.788705 | controller |
2026-06-08 13:10:29.788860 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 13:10:29.789071 | controller | Monday 08 June 2026  13:10:29 +0000 (0:00:00.020)       0:00:47.112 ***********
2026-06-08 13:10:30.101997 | controller | ok: [instance]
2026-06-08 13:10:30.102073 | controller |
2026-06-08 13:10:30.102082 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 13:10:30.102087 | controller | Monday 08 June 2026  13:10:30 +0000 (0:00:00.313)       0:00:47.426 ***********
2026-06-08 13:10:40.136272 | controller | Pausing for 10 seconds
2026-06-08 13:10:40.136354 | controller | ok: [instance]
2026-06-08 13:10:40.136361 | controller |
2026-06-08 13:10:40.136367 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 13:10:40.136372 | controller | Monday 08 June 2026  13:10:40 +0000 (0:00:10.033)       0:00:57.460 ***********
2026-06-08 13:10:40.488475 | controller | ok: [instance]
2026-06-08 13:10:40.488548 | controller |
2026-06-08 13:10:40.488565 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 13:10:40.488674 | controller | Monday 08 June 2026  13:10:40 +0000 (0:00:00.351)       0:00:57.812 ***********
2026-06-08 13:10:40.900250 | controller | ok: [instance]
2026-06-08 13:10:40.900327 | controller |
2026-06-08 13:10:40.900337 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 13:10:40.900343 | controller | Monday 08 June 2026  13:10:40 +0000 (0:00:00.412)       0:00:58.224 ***********
2026-06-08 13:10:40.938538 | controller | ok: [instance] => {
2026-06-08 13:10:40.938599 | controller |     "changed": false,
2026-06-08 13:10:40.938606 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:40.938612 | controller | }
2026-06-08 13:10:40.938617 | controller |
2026-06-08 13:10:40.938622 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 13:10:40.938628 | controller | Monday 08 June 2026  13:10:40 +0000 (0:00:00.037)       0:00:58.262 ***********
2026-06-08 13:10:40.956492 | controller | ok: [instance] => {
2026-06-08 13:10:40.956549 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:40.956653 | controller | }
2026-06-08 13:10:40.956754 | controller |
2026-06-08 13:10:40.956877 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 13:10:40.957020 | controller | Monday 08 June 2026  13:10:40 +0000 (0:00:00.018)       0:00:58.281 ***********
2026-06-08 13:10:41.310501 | controller | ok: [instance]
2026-06-08 13:10:41.310551 | controller |
2026-06-08 13:10:41.310696 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 13:10:41.310837 | controller | Monday 08 June 2026  13:10:41 +0000 (0:00:00.353)       0:00:58.634 ***********
2026-06-08 13:10:41.350010 | controller | ok: [instance] => {
2026-06-08 13:10:41.350119 | controller |     "changed": false,
2026-06-08 13:10:41.350220 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:41.350422 | controller | }
2026-06-08 13:10:41.350564 | controller |
2026-06-08 13:10:41.350687 | controller | TASK [Query mock state] ********************************************************
2026-06-08 13:10:41.350827 | controller | Monday 08 June 2026  13:10:41 +0000 (0:00:00.039)       0:00:58.674 ***********
2026-06-08 13:10:41.753894 | controller | ok: [instance]
2026-06-08 13:10:41.753984 | controller |
2026-06-08 13:10:41.754145 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-06-08 13:10:41.754290 | controller | Monday 08 June 2026  13:10:41 +0000 (0:00:00.403)       0:00:59.077 ***********
2026-06-08 13:10:41.781450 | controller | ok: [instance] => {
2026-06-08 13:10:41.781559 | controller |     "changed": false,
2026-06-08 13:10:41.781687 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:41.781814 | controller | }
2026-06-08 13:10:41.781952 | controller |
2026-06-08 13:10:41.782108 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 13:10:41.782259 | controller | Monday 08 June 2026  13:10:41 +0000 (0:00:00.027)       0:00:59.105 ***********
2026-06-08 13:10:41.802494 | controller | ok: [instance]
2026-06-08 13:10:41.802591 | controller |
2026-06-08 13:10:41.802741 | controller | TASK [Reset mock without Virtual Optical Drive] ********************************
2026-06-08 13:10:41.802854 | controller | Monday 08 June 2026  13:10:41 +0000 (0:00:00.021)       0:00:59.126 ***********
2026-06-08 13:10:42.133163 | controller | ok: [instance]
2026-06-08 13:10:42.133196 | controller |
2026-06-08 13:10:42.133201 | controller | TASK [Include bm_discover_vmedia_target (floppy fallback)] *********************
2026-06-08 13:10:42.133206 | controller | Monday 08 June 2026  13:10:42 +0000 (0:00:00.330)       0:00:59.457 ***********
2026-06-08 13:10:42.167092 | controller |
2026-06-08 13:10:42.167131 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 13:10:42.167139 | controller | Monday 08 June 2026  13:10:42 +0000 (0:00:00.034)       0:00:59.491 ***********
2026-06-08 13:10:42.515966 | controller | ok: [instance]
2026-06-08 13:10:42.515995 | controller |
2026-06-08 13:10:42.516004 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 13:10:42.516009 | controller | Monday 08 June 2026  13:10:42 +0000 (0:00:00.348)       0:00:59.840 ***********
2026-06-08 13:10:43.790471 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:43.791113 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:43.791144 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:43.791148 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:43.791152 | controller | ok: [instance]
2026-06-08 13:10:43.791157 | controller |
2026-06-08 13:10:43.791161 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 13:10:43.791165 | controller | Monday 08 June 2026  13:10:43 +0000 (0:00:01.274)       0:01:01.115 ***********
2026-06-08 13:10:43.828204 | controller | ok: [instance]
2026-06-08 13:10:43.828237 | controller |
2026-06-08 13:10:43.828242 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 13:10:43.828247 | controller | Monday 08 June 2026  13:10:43 +0000 (0:00:00.037)       0:01:01.152 ***********
2026-06-08 13:10:43.864443 | controller | ok: [instance] => {
2026-06-08 13:10:43.864484 | controller |     "msg": [
2026-06-08 13:10:43.864493 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 13:10:43.864499 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 13:10:43.864505 | controller |         "Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi",
2026-06-08 13:10:43.864512 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:10:43.864518 | controller |     ]
2026-06-08 13:10:43.864524 | controller | }
2026-06-08 13:10:43.864529 | controller |
2026-06-08 13:10:43.864535 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 13:10:43.864626 | controller | Monday 08 June 2026  13:10:43 +0000 (0:00:00.035)       0:01:01.187 ***********
2026-06-08 13:10:43.894816 | controller | skipping: [instance]
2026-06-08 13:10:43.894851 | controller |
2026-06-08 13:10:43.894857 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 13:10:43.894861 | controller | Monday 08 June 2026  13:10:43 +0000 (0:00:00.031)       0:01:01.219 ***********
2026-06-08 13:10:43.959576 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:43.959762 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:43.959910 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:43.960054 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:43.960198 | controller | skipping: [instance]
2026-06-08 13:10:43.960350 | controller |
2026-06-08 13:10:43.960505 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 13:10:43.960648 | controller | Monday 08 June 2026  13:10:43 +0000 (0:00:00.064)       0:01:01.284 ***********
2026-06-08 13:10:44.021788 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:44.022016 | controller | ok: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:44.022221 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:44.022435 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:44.022647 | controller |
2026-06-08 13:10:44.022827 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 13:10:44.023005 | controller | Monday 08 June 2026  13:10:44 +0000 (0:00:00.062)       0:01:01.346 ***********
2026-06-08 13:10:44.077379 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:44.077585 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 13:10:44.077741 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:44.077901 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:44.078070 | controller | skipping: [instance]
2026-06-08 13:10:44.078226 | controller |
2026-06-08 13:10:44.078415 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 13:10:44.078624 | controller | Monday 08 June 2026  13:10:44 +0000 (0:00:00.055)       0:01:01.401 ***********
2026-06-08 13:10:44.110277 | controller | skipping: [instance]
2026-06-08 13:10:44.110516 | controller |
2026-06-08 13:10:44.110715 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 13:10:44.110881 | controller | Monday 08 June 2026  13:10:44 +0000 (0:00:00.033)       0:01:01.434 ***********
2026-06-08 13:10:44.128788 | controller | ok: [instance] => {
2026-06-08 13:10:44.128966 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:44.129095 | controller | }
2026-06-08 13:10:44.129232 | controller |
2026-06-08 13:10:44.129394 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 13:10:44.129530 | controller | Monday 08 June 2026  13:10:44 +0000 (0:00:00.018)       0:01:01.453 ***********
2026-06-08 13:10:44.478107 | controller | ok: [instance]
2026-06-08 13:10:44.478261 | controller |
2026-06-08 13:10:44.478463 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 13:10:44.478600 | controller | Monday 08 June 2026  13:10:44 +0000 (0:00:00.349)       0:01:01.802 ***********
2026-06-08 13:10:54.509458 | controller | Pausing for 10 seconds
2026-06-08 13:10:54.509543 | controller | ok: [instance]
2026-06-08 13:10:54.509664 | controller |
2026-06-08 13:10:54.509801 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 13:10:54.509931 | controller | Monday 08 June 2026  13:10:54 +0000 (0:00:10.031)       0:01:11.833 ***********
2026-06-08 13:10:54.855668 | controller | ok: [instance]
2026-06-08 13:10:54.855800 | controller |
2026-06-08 13:10:54.855965 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 13:10:54.856079 | controller | Monday 08 June 2026  13:10:54 +0000 (0:00:00.346)       0:01:12.180 ***********
2026-06-08 13:10:55.186071 | controller | ok: [instance]
2026-06-08 13:10:55.186102 | controller |
2026-06-08 13:10:55.186108 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 13:10:55.186113 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.330)       0:01:12.510 ***********
2026-06-08 13:10:55.229206 | controller | ok: [instance] => {
2026-06-08 13:10:55.229238 | controller |     "changed": false,
2026-06-08 13:10:55.229243 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:55.229254 | controller | }
2026-06-08 13:10:55.229259 | controller |
2026-06-08 13:10:55.229263 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 13:10:55.229267 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.042)       0:01:12.552 ***********
2026-06-08 13:10:55.250520 | controller | ok: [instance] => {
2026-06-08 13:10:55.250557 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 13:10:55.250562 | controller | }
2026-06-08 13:10:55.250566 | controller |
2026-06-08 13:10:55.250570 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 13:10:55.250574 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.021)       0:01:12.574 ***********
2026-06-08 13:10:55.571723 | controller | ok: [instance]
2026-06-08 13:10:55.571756 | controller |
2026-06-08 13:10:55.571761 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 13:10:55.571766 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.321)       0:01:12.895 ***********
2026-06-08 13:10:55.612503 | controller | ok: [instance] => {
2026-06-08 13:10:55.612540 | controller |     "changed": false,
2026-06-08 13:10:55.612546 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:55.612552 | controller | }
2026-06-08 13:10:55.612558 | controller |
2026-06-08 13:10:55.612710 | controller | TASK [Assert derived path uses Unit(0x0) from Floppy Unit(0x1)] ****************
2026-06-08 13:10:55.612743 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.040)       0:01:12.936 ***********
2026-06-08 13:10:55.656239 | controller | ok: [instance] => {
2026-06-08 13:10:55.656276 | controller |     "changed": false,
2026-06-08 13:10:55.656281 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:55.656285 | controller | }
2026-06-08 13:10:55.656290 | controller |
2026-06-08 13:10:55.656293 | controller | TASK [Query mock state after floppy fallback] **********************************
2026-06-08 13:10:55.656298 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.043)       0:01:12.979 ***********
2026-06-08 13:10:55.981821 | controller | ok: [instance]
2026-06-08 13:10:55.981851 | controller |
2026-06-08 13:10:55.981856 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 13:10:55.981861 | controller | Monday 08 June 2026  13:10:55 +0000 (0:00:00.325)       0:01:13.305 ***********
2026-06-08 13:10:56.002546 | controller | ok: [instance] => {
2026-06-08 13:10:56.002593 | controller |     "changed": false,
2026-06-08 13:10:56.002985 | controller |     "msg": "All assertions passed"
2026-06-08 13:10:56.003013 | controller | }
2026-06-08 13:10:56.003018 | controller |
2026-06-08 13:10:56.003022 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 13:10:56.003027 | controller | Monday 08 June 2026  13:10:56 +0000 (0:00:00.021)       0:01:13.327 ***********
2026-06-08 13:10:56.019928 | controller | ok: [instance]
2026-06-08 13:10:56.019960 | controller |
2026-06-08 13:10:56.019965 | controller | TASK [Reset mock without Virtual Optical or Floppy Drive] **********************
2026-06-08 13:10:56.019969 | controller | Monday 08 June 2026  13:10:56 +0000 (0:00:00.017)       0:01:13.344 ***********
2026-06-08 13:10:56.334981 | controller | ok: [instance]
2026-06-08 13:10:56.335014 | controller |
2026-06-08 13:10:56.335020 | controller | TASK [Include bm_discover_vmedia_target (generic usb fallback)] ****************
2026-06-08 13:10:56.335025 | controller | Monday 08 June 2026  13:10:56 +0000 (0:00:00.314)       0:01:13.659 ***********
2026-06-08 13:10:56.373890 | controller |
2026-06-08 13:10:56.373927 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 13:10:56.373932 | controller | Monday 08 June 2026  13:10:56 +0000 (0:00:00.038)       0:01:13.697 ***********
2026-06-08 13:10:56.740541 | controller | ok: [instance]
2026-06-08 13:10:56.740581 | controller |
2026-06-08 13:10:56.740736 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 13:10:56.740771 | controller | Monday 08 June 2026  13:10:56 +0000 (0:00:00.367)       0:01:14.064 ***********
2026-06-08 13:10:57.754104 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:57.754146 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:57.754155 | controller | ok: [instance] => (item=None)
2026-06-08 13:10:57.754163 | controller | ok: [instance]
2026-06-08 13:10:57.754171 | controller |
2026-06-08 13:10:57.754179 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 13:10:57.754201 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:01.012)       0:01:15.077 ***********
2026-06-08 13:10:57.791432 | controller | ok: [instance]
2026-06-08 13:10:57.791466 | controller |
2026-06-08 13:10:57.791473 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 13:10:57.791479 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:00.037)       0:01:15.115 ***********
2026-06-08 13:10:57.826472 | controller | ok: [instance] => {
2026-06-08 13:10:57.826510 | controller |     "msg": [
2026-06-08 13:10:57.826518 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 13:10:57.826524 | controller |         "Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi",
2026-06-08 13:10:57.826530 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:10:57.826536 | controller |     ]
2026-06-08 13:10:57.826542 | controller | }
2026-06-08 13:10:57.826968 | controller |
2026-06-08 13:10:57.827003 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 13:10:57.827010 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:00.034)       0:01:15.150 ***********
2026-06-08 13:10:57.854447 | controller | skipping: [instance]
2026-06-08 13:10:57.854802 | controller |
2026-06-08 13:10:57.855164 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 13:10:57.855543 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:00.028)       0:01:15.178 ***********
2026-06-08 13:10:57.911811 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:57.911910 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:57.912029 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:57.912141 | controller | skipping: [instance]
2026-06-08 13:10:57.912241 | controller |
2026-06-08 13:10:57.912421 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 13:10:57.912530 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:00.057)       0:01:15.236 ***********
2026-06-08 13:10:57.965863 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:57.966111 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:57.966336 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:57.966544 | controller | skipping: [instance]
2026-06-08 13:10:57.966789 | controller |
2026-06-08 13:10:57.967054 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 13:10:57.967247 | controller | Monday 08 June 2026  13:10:57 +0000 (0:00:00.053)       0:01:15.290 ***********
2026-06-08 13:10:58.024144 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 13:10:58.024288 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 13:10:58.024449 | controller | ok: [instance] => (item=Generic USB Boot)
2026-06-08 13:10:58.024610 | controller |
2026-06-08 13:10:58.024769 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 13:10:58.024917 | controller | Monday 08 June 2026  13:10:58 +0000 (0:00:00.058)       0:01:15.348 ***********
2026-06-08 13:10:58.055113 | controller | skipping: [instance]
2026-06-08 13:10:58.055217 | controller |
2026-06-08 13:10:58.055338 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 13:10:58.055482 | controller | Monday 08 June 2026  13:10:58 +0000 (0:00:00.030)       0:01:15.379 ***********
2026-06-08 13:10:58.081694 | controller | ok: [instance] => {
2026-06-08 13:10:58.081786 | controller |     "msg": "VirtualMedia UEFI path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:10:58.081897 | controller | }
2026-06-08 13:10:58.082002 | controller |
2026-06-08 13:10:58.082232 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 13:10:58.082383 | controller | Monday 08 June 2026  13:10:58 +0000 (0:00:00.026)       0:01:15.406 ***********
2026-06-08 13:10:58.422176 | controller | ok: [instance]
2026-06-08 13:10:58.422211 | controller |
2026-06-08 13:10:58.422218 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 13:10:58.422224 | controller | Monday 08 June 2026  13:10:58 +0000 (0:00:00.339)       0:01:15.746 ***********
2026-06-08 13:11:08.451128 | controller | Pausing for 10 seconds
2026-06-08 13:11:08.451158 | controller | ok: [instance]
2026-06-08 13:11:08.451163 | controller |
2026-06-08 13:11:08.451167 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 13:11:08.451171 | controller | Monday 08 June 2026  13:11:08 +0000 (0:00:10.028)       0:01:25.775 ***********
2026-06-08 13:11:08.778035 | controller | ok: [instance]
2026-06-08 13:11:08.778073 | controller |
2026-06-08 13:11:08.778080 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 13:11:08.778086 | controller | Monday 08 June 2026  13:11:08 +0000 (0:00:00.326)       0:01:26.101 ***********
2026-06-08 13:11:09.090441 | controller | ok: [instance]
2026-06-08 13:11:09.090501 | controller |
2026-06-08 13:11:09.090508 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 13:11:09.090512 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.312)       0:01:26.414 ***********
2026-06-08 13:11:09.139193 | controller | ok: [instance] => {
2026-06-08 13:11:09.139223 | controller |     "changed": false,
2026-06-08 13:11:09.139228 | controller |     "msg": "All assertions passed"
2026-06-08 13:11:09.139233 | controller | }
2026-06-08 13:11:09.139237 | controller |
2026-06-08 13:11:09.139240 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 13:11:09.139245 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.048)       0:01:26.463 ***********
2026-06-08 13:11:09.165245 | controller | ok: [instance] => {
2026-06-08 13:11:09.165273 | controller |     "msg": "Resolved boot path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:11:09.165278 | controller | }
2026-06-08 13:11:09.165282 | controller |
2026-06-08 13:11:09.165286 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 13:11:09.165290 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.026)       0:01:26.489 ***********
2026-06-08 13:11:09.498333 | controller | ok: [instance]
2026-06-08 13:11:09.498367 | controller |
2026-06-08 13:11:09.498373 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 13:11:09.498379 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.333)       0:01:26.822 ***********
2026-06-08 13:11:09.536291 | controller | ok: [instance] => {
2026-06-08 13:11:09.536342 | controller |     "changed": false,
2026-06-08 13:11:09.536347 | controller |     "msg": "All assertions passed"
2026-06-08 13:11:09.536352 | controller | }
2026-06-08 13:11:09.536356 | controller |
2026-06-08 13:11:09.536360 | controller | TASK [Assert Generic USB Boot path was used] ***********************************
2026-06-08 13:11:09.536364 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.037)       0:01:26.860 ***********
2026-06-08 13:11:09.579987 | controller | ok: [instance] => {
2026-06-08 13:11:09.580199 | controller |     "changed": false,
2026-06-08 13:11:09.580428 | controller |     "msg": "All assertions passed"
2026-06-08 13:11:09.580588 | controller | }
2026-06-08 13:11:09.580710 | controller |
2026-06-08 13:11:09.580869 | controller | TASK [Query mock state after generic usb fallback] *****************************
2026-06-08 13:11:09.581040 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.044)       0:01:26.904 ***********
2026-06-08 13:11:09.937803 | controller | ok: [instance]
2026-06-08 13:11:09.937969 | controller |
2026-06-08 13:11:09.938100 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 13:11:09.938227 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.357)       0:01:27.262 ***********
2026-06-08 13:11:09.968962 | controller | ok: [instance] => {
2026-06-08 13:11:09.969190 | controller |     "changed": false,
2026-06-08 13:11:09.969373 | controller |     "msg": "All assertions passed"
2026-06-08 13:11:09.969530 | controller | }
2026-06-08 13:11:09.969677 | controller |
2026-06-08 13:11:09.969839 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 13:11:09.970012 | controller | Monday 08 June 2026  13:11:09 +0000 (0:00:00.030)       0:01:27.293 ***********
2026-06-08 13:11:10.314371 | controller | ok: [instance]
2026-06-08 13:11:10.314610 | controller |
2026-06-08 13:11:10.314792 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-06-08 13:11:10.314959 | controller | Monday 08 June 2026  13:11:10 +0000 (0:00:00.345)       0:01:27.638 ***********
2026-06-08 13:11:10.357023 | controller |
2026-06-08 13:11:10.357252 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 13:11:10.357462 | controller | Monday 08 June 2026  13:11:10 +0000 (0:00:00.042)       0:01:27.681 ***********
2026-06-08 13:11:10.721149 | controller | ok: [instance]
2026-06-08 13:11:10.721183 | controller |
2026-06-08 13:11:10.721189 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 13:11:10.721195 | controller | Monday 08 June 2026  13:11:10 +0000 (0:00:00.363)       0:01:28.045 ***********
2026-06-08 13:11:12.439279 | controller | ok: [instance] => (item=None)
2026-06-08 13:11:12.439333 | controller | ok: [instance] => (item=None)
2026-06-08 13:11:12.439342 | controller | ok: [instance] => (item=None)
2026-06-08 13:11:12.439347 | controller | ok: [instance] => (item=None)
2026-06-08 13:11:12.439352 | controller | ok: [instance] => (item=None)
2026-06-08 13:11:12.439357 | controller | ok: [instance]
2026-06-08 13:11:12.439363 | controller |
2026-06-08 13:11:12.439368 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 13:11:12.439374 | controller | Monday 08 June 2026  13:11:12 +0000 (0:00:01.717)       0:01:29.762 ***********
2026-06-08 13:11:12.477095 | controller | ok: [instance]
2026-06-08 13:11:12.477126 | controller |
2026-06-08 13:11:12.477131 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 13:11:12.477136 | controller | Monday 08 June 2026  13:11:12 +0000 (0:00:00.038)       0:01:29.801 ***********
2026-06-08 13:11:12.514636 | controller | ok: [instance] => {
2026-06-08 13:11:12.514676 | controller |     "msg": [
2026-06-08 13:11:12.515767 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 13:11:12.515805 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 13:11:12.515811 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 13:11:12.515817 | controller |         "Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi",
2026-06-08 13:11:12.515823 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 13:11:12.515828 | controller |     ]
2026-06-08 13:11:12.515833 | controller | }
2026-06-08 13:11:12.515838 | controller |
2026-06-08 13:11:12.515843 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 13:11:12.515848 | controller | Monday 08 June 2026  13:11:12 +0000 (0:00:00.037)       0:01:29.838 ***********
2026-06-08 13:11:12.560592 | controller | fatal: [instance]: FAILED! => {
2026-06-08 13:11:12.560781 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-06-08 13:11:12.560931 | controller |     "changed": false,
2026-06-08 13:11:12.561094 | controller |     "evaluated_to": false,
2026-06-08 13:11:12.561292 | 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-06-08 13:11:12.561489 | controller | }
2026-06-08 13:11:12.564934 | controller |
2026-06-08 13:11:12.565147 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-06-08 13:11:12.565365 | controller | Monday 08 June 2026  13:11:12 +0000 (0:00:00.050)       0:01:29.889 ***********
2026-06-08 13:11:12.607270 | controller | ok: [instance] => {
2026-06-08 13:11:12.607517 | controller |     "changed": false,
2026-06-08 13:11:12.607689 | controller |     "msg": "All assertions passed"
2026-06-08 13:11:12.607877 | controller | }
2026-06-08 13:11:12.608053 | controller |
2026-06-08 13:11:12.608237 | controller | PLAY RECAP *********************************************************************
2026-06-08 13:11:12.608455 | controller | instance                   : ok=168  changed=0    unreachable=0    failed=0    skipped=28   rescued=5    ignored=0
2026-06-08 13:11:12.608594 | controller |
2026-06-08 13:11:12.608786 | controller | Monday 08 June 2026  13:11:12 +0000 (0:00:00.041)       0:01:29.931 ***********
2026-06-08 13:11:12.608946 | controller | ===============================================================================
2026-06-08 13:11:12.609112 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 13:11:12.609277 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.03s
2026-06-08 13:11:12.609458 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.03s
2026-06-08 13:11:12.609587 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.03s
2026-06-08 13:11:12.609712 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.03s
2026-06-08 13:11:12.609840 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.02s
2026-06-08 13:11:12.609969 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.76s
2026-06-08 13:11:12.610097 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.72s
2026-06-08 13:11:12.610374 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.58s
2026-06-08 13:11:12.610749 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.27s
2026-06-08 13:11:12.610931 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.01s
2026-06-08 13:11:12.611110 | controller | Reset mock to power Off ------------------------------------------------- 0.43s
2026-06-08 13:11:12.611289 | controller | bm_sno : Wait for host to power off ------------------------------------- 0.42s
2026-06-08 13:11:12.611487 | controller | bm_sno : Verify VirtualMedia is still inserted -------------------------- 0.42s
2026-06-08 13:11:12.611665 | controller | bm_sno : Verify boot override was applied ------------------------------- 0.41s
2026-06-08 13:11:12.611840 | controller | bm_sno : Read GenericUsbBoot BIOS attribute ----------------------------- 0.41s
2026-06-08 13:11:12.612007 | controller | Query mock state -------------------------------------------------------- 0.40s
2026-06-08 13:11:12.612182 | controller | bm_sno : Query current power state -------------------------------------- 0.40s
2026-06-08 13:11:12.612384 | controller | Reset mock with usb_boot Disabled --------------------------------------- 0.40s
2026-06-08 13:11:12.612561 | controller | bm_sno : Wait for host POST to complete --------------------------------- 0.38s
2026-06-08 13:11:12.702754 | controller | INFO     Running bm_redfish > cleanup
2026-06-08 13:11:13.217904 | controller |
2026-06-08 13:11:13.218152 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-06-08 13:11:13.218297 | controller |
2026-06-08 13:11:13.218476 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-06-08 13:11:13.218610 | controller | Monday 08 June 2026  13:11:13 +0000 (0:00:00.028)       0:00:00.028 ***********
2026-06-08 13:11:13.562186 | controller | ok: [instance]
2026-06-08 13:11:13.562217 | controller |
2026-06-08 13:11:13.562222 | controller | TASK [Show mock server log] ****************************************************
2026-06-08 13:11:13.562226 | controller | Monday 08 June 2026  13:11:13 +0000 (0:00:00.344)       0:00:00.372 ***********
2026-06-08 13:11:13.773541 | controller | ok: [instance]
2026-06-08 13:11:13.773574 | controller |
2026-06-08 13:11:13.773579 | controller | TASK [Print mock server log] ***************************************************
2026-06-08 13:11:13.773621 | controller | Monday 08 June 2026  13:11:13 +0000 (0:00:00.211)       0:00:00.584 ***********
2026-06-08 13:11:13.807559 | controller | ok: [instance] => {
2026-06-08 13:11:13.807611 | controller |     "_mock_log.stdout_lines": [
2026-06-08 13:11:13.807619 | controller |         "Mock iDRAC listening on https://0.0.0.0:8443",
2026-06-08 13:11:13.810425 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810463 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810467 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810472 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810475 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810478 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810482 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 13:11:13.810486 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810489 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810493 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810496 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810500 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810503 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810507 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810510 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810514 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 13:11:13.810517 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810520 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810524 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810527 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810531 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 13:11:13.810534 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810538 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810541 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810549 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810707 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.810852 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811020 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811194 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811476 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811610 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811758 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 13:11:13.811914 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1/Bios/Settings HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812067 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/Jobs HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812222 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812372 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812504 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 13:11:13.812617 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812723 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.812833 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 13:11:13.812993 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813150 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813265 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813415 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813587 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813729 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 13:11:13.813842 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.813972 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814089 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 13:11:13.814194 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814300 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814467 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814611 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814745 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.814891 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.815354 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.815504 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.815645 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 13:11:13.815793 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.815914 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816040 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816133 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816240 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816375 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816499 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816612 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816728 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816838 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.816957 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817125 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817249 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817376 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817681 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817788 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.817898 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818008 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818117 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818225 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818341 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818515 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818631 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818740 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818849 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.818956 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819067 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819171 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819304 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819432 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819544 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819652 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819765 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819879 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.819987 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820099 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820205 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820320 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820435 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820548 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820655 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820762 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820874 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 13:11:13.820976 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -"
2026-06-08 13:11:13.821080 | controller |     ]
2026-06-08 13:11:13.821243 | controller | }
2026-06-08 13:11:13.823655 | controller |
2026-06-08 13:11:13.823795 | controller | PLAY RECAP *********************************************************************
2026-06-08 13:11:13.823971 | controller | instance                   : ok=3    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 13:11:13.824083 | controller |
2026-06-08 13:11:13.824194 | controller | Monday 08 June 2026  13:11:13 +0000 (0:00:00.050)       0:00:00.634 ***********
2026-06-08 13:11:13.824369 | controller | ===============================================================================
2026-06-08 13:11:13.824487 | controller | Stop mock iDRAC server -------------------------------------------------- 0.34s
2026-06-08 13:11:13.824599 | controller | Show mock server log ---------------------------------------------------- 0.21s
2026-06-08 13:11:13.824711 | controller | Print mock server log --------------------------------------------------- 0.05s
2026-06-08 13:11:13.888554 | controller | INFO     Writing /tmp/report.html report.
2026-06-08 13:11:14.067657 | controller | ok: Runtime: 0:01:35.691032
2026-06-08 13:11:14.088601 | 
2026-06-08 13:11:14.088713 | PLAY RECAP
2026-06-08 13:11:14.088796 | controller | ok: 4 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 13:11:14.088840 | 
2026-06-08 13:11:14.223397 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 13:11:14.226013 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 13:11:14.844695 | 
2026-06-08 13:11:14.844805 | PLAY [Ensure ci-framework-data base directories exist on all nodes]
2026-06-08 13:11:14.856744 | 
2026-06-08 13:11:14.856814 | TASK [Create ci-framework-data/logs directory if missing]
2026-06-08 13:11:15.300224 | controller | ok
2026-06-08 13:11:15.320138 | 
2026-06-08 13:11:15.320222 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-06-08 13:11:15.324742 | 
2026-06-08 13:11:15.324818 | TASK [Filter out host if needed]
2026-06-08 13:11:15.332138 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-06-08 13:11:15.335038 | 
2026-06-08 13:11:15.335101 | TASK [Ensure file is present]
2026-06-08 13:11:15.742184 | controller | ok
2026-06-08 13:11:15.753948 | 
2026-06-08 13:11:15.754085 | TASK [Manage molecule report file]
2026-06-08 13:11:16.306427 | controller | ok: Runtime: 0:00:00.003883
2026-06-08 13:11:16.314961 | 
2026-06-08 13:11:16.315085 | TASK [Check if we get ci-framework-data basedir]
2026-06-08 13:11:16.530416 | controller | ok
2026-06-08 13:11:16.538677 | 
2026-06-08 13:11:16.538808 | TASK [Create ci-framework-data log directory for zuul]
2026-06-08 13:11:16.807016 | controller | changed
2026-06-08 13:11:16.815543 | 
2026-06-08 13:11:16.815680 | TASK [Copy ci-framework interesting files]
2026-06-08 13:11:17.047240 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-06-08 13:11:17.363863 | controller | ok: Runtime: 0:00:00.009318
2026-06-08 13:11:17.371453 | 
2026-06-08 13:11:17.371653 | TASK [Get SELinux listing]
2026-06-08 13:11:17.916436 | controller | ok: Runtime: 0:00:00.008519
2026-06-08 13:11:17.920392 | 
2026-06-08 13:11:17.920447 | TASK [Generate log index]
2026-06-08 13:11:18.675033 | controller | changed
2026-06-08 13:11:18.685057 | 
2026-06-08 13:11:18.685190 | TASK [Get some env related data]
2026-06-08 13:11:19.303028 | controller | /home/zuul/.local/bin/ansible
2026-06-08 13:11:20.235180 | controller | ok: Runtime: 0:00:01.045753
2026-06-08 13:11:20.283432 | 
2026-06-08 13:11:20.283706 | TASK [Generate list of logs to collect in home directory]
2026-06-08 13:11:20.605469 | controller | ok: All paths examined
2026-06-08 13:11:20.613649 | 
2026-06-08 13:11:20.613770 | LOOP [Copy logs from home directory]
2026-06-08 13:11:20.961210 | controller | changed:
2026-06-08 13:11:20.961369 | controller | {
2026-06-08 13:11:20.961394 | controller |   "atime": 1780924137.1202335,
2026-06-08 13:11:20.961412 | controller |   "ctime": 1780924175.4465964,
2026-06-08 13:11:20.961428 | controller |   "dev": 64513,
2026-06-08 13:11:20.961443 | controller |   "gid": 1000,
2026-06-08 13:11:20.961458 | controller |   "gr_name": "zuul",
2026-06-08 13:11:20.961474 | controller |   "inode": 241338,
2026-06-08 13:11:20.961490 | controller |   "isblk": false,
2026-06-08 13:11:20.961505 | controller |   "ischr": false,
2026-06-08 13:11:20.961545 | controller |   "isdir": false,
2026-06-08 13:11:20.961560 | controller |   "isfifo": false,
2026-06-08 13:11:20.961575 | controller |   "isgid": false,
2026-06-08 13:11:20.961589 | controller |   "islnk": false,
2026-06-08 13:11:20.961603 | controller |   "isreg": true,
2026-06-08 13:11:20.961618 | controller |   "issock": false,
2026-06-08 13:11:20.961639 | controller |   "isuid": false,
2026-06-08 13:11:20.961654 | controller |   "mode": "0644",
2026-06-08 13:11:20.961669 | controller |   "mtime": 1780924175.4465964,
2026-06-08 13:11:20.961684 | controller |   "nlink": 1,
2026-06-08 13:11:20.961699 | controller |   "path": "/home/zuul/ansible.log",
2026-06-08 13:11:20.961731 | controller |   "pw_name": "zuul",
2026-06-08 13:11:20.961748 | controller |   "rgrp": true,
2026-06-08 13:11:20.961764 | controller |   "roth": true,
2026-06-08 13:11:20.961788 | controller |   "rusr": true,
2026-06-08 13:11:20.961804 | controller |   "size": 6749,
2026-06-08 13:11:20.961819 | controller |   "uid": 1000,
2026-06-08 13:11:20.961834 | controller |   "wgrp": false,
2026-06-08 13:11:20.961848 | controller |   "woth": false,
2026-06-08 13:11:20.961863 | controller |   "wusr": true,
2026-06-08 13:11:20.961877 | controller |   "xgrp": false,
2026-06-08 13:11:20.961891 | controller |   "xoth": false,
2026-06-08 13:11:20.961906 | controller |   "xusr": false
2026-06-08 13:11:20.961921 | controller | }
2026-06-08 13:11:20.972348 | 
2026-06-08 13:11:20.972594 | TASK [Copy crio stats log file]
2026-06-08 13:11:20.998324 | controller | skipping: Conditional result was False
2026-06-08 13:11:21.007706 | 
2026-06-08 13:11:21.007880 | TASK [Get SELinux related data]
2026-06-08 13:11:21.289346 | controller | <no matches>
2026-06-08 13:11:21.555677 | controller | ERROR
2026-06-08 13:11:21.555893 | controller | {
2026-06-08 13:11:21.555928 | controller |   "delta": "0:00:00.009773",
2026-06-08 13:11:21.555957 | controller |   "end": "2026-06-08 13:11:21.290274",
2026-06-08 13:11:21.555978 | controller |   "msg": "non-zero return code",
2026-06-08 13:11:21.555997 | controller |   "rc": 1,
2026-06-08 13:11:21.556018 | controller |   "start": "2026-06-08 13:11:21.280501"
2026-06-08 13:11:21.556039 | controller | }
2026-06-08 13:11:21.556065 | controller | ERROR: Ignoring Errors
2026-06-08 13:11:21.560580 | 
2026-06-08 13:11:21.560657 | TASK [Create system configuration directory]
2026-06-08 13:11:21.806025 | controller | changed
2026-06-08 13:11:21.813728 | 
2026-06-08 13:11:21.813856 | TASK [Get some of the system configurations]
2026-06-08 13:11:22.365474 | controller | ok: Runtime: 0:00:00.013634
2026-06-08 13:11:22.373032 | 
2026-06-08 13:11:22.373158 | TASK [Copy generated documentation if available]
2026-06-08 13:11:22.398892 | controller | skipping: Conditional result was False
2026-06-08 13:11:22.407345 | 
2026-06-08 13:11:22.407475 | TASK [Copy generated AsciiDoc documentation if available]
2026-06-08 13:11:22.433876 | controller | skipping: Conditional result was False
2026-06-08 13:11:22.442432 | 
2026-06-08 13:11:22.442605 | TASK [Compress logs bigger than 2MB]
2026-06-08 13:11:22.988801 | controller | ok: Runtime: 0:00:00.003782
2026-06-08 13:11:22.996343 | 
2026-06-08 13:11:22.996466 | TASK [Copy files from workspace on node]
2026-06-08 13:11:23.020934 | controller | ok
2026-06-08 13:11:23.062904 | 
2026-06-08 13:11:23.063046 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 13:11:23.097683 | controller | skipping: Conditional result was False
2026-06-08 13:11:23.103167 | 
2026-06-08 13:11:23.103252 | TASK [fetch-output : Set log path for single node]
2026-06-08 13:11:23.145829 | controller | ok
2026-06-08 13:11:23.153586 | 
2026-06-08 13:11:23.153714 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 13:11:23.459176 | controller -> localhost | changed: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/logs"
2026-06-08 13:11:23.459713 | controller -> localhost | changed: All items complete
2026-06-08 13:11:23.459775 | 
2026-06-08 13:11:23.678984 | controller -> localhost | changed: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/artifacts"
2026-06-08 13:11:23.931991 | controller -> localhost | changed: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/docs"
2026-06-08 13:11:23.945379 | 
2026-06-08 13:11:23.945499 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 13:11:24.644135 | controller | changed:
2026-06-08 13:11:24.644452 | controller | .d..t...... ./
2026-06-08 13:11:24.644541 | controller | >f+++++++++ README.html
2026-06-08 13:11:24.644599 | controller | >f+++++++++ ansible-execution.log
2026-06-08 13:11:24.644639 | controller | >f+++++++++ ansible.log
2026-06-08 13:11:24.644680 | controller | >f+++++++++ dmesg.log
2026-06-08 13:11:24.644720 | controller | >f+++++++++ installed-pkgs.log
2026-06-08 13:11:24.644758 | controller | >f+++++++++ python.log
2026-06-08 13:11:24.644793 | controller | >f+++++++++ registries.conf
2026-06-08 13:11:24.644828 | controller | >f+++++++++ report.html
2026-06-08 13:11:24.644863 | controller | >f+++++++++ selinux-denials.log
2026-06-08 13:11:24.644898 | controller | >f+++++++++ selinux-listing.log
2026-06-08 13:11:24.644932 | controller | cd+++++++++ ci-framework-data/
2026-06-08 13:11:24.644967 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-06-08 13:11:24.645002 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-06-08 13:11:24.645037 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-06-08 13:11:24.645072 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-06-08 13:11:24.645109 | controller | cd+++++++++ ci-framework-data/logs/
2026-06-08 13:11:24.645145 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-06-08 13:11:24.645181 | controller | cd+++++++++ registries.conf.d/
2026-06-08 13:11:24.645217 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-06-08 13:11:24.645262 | controller | cd+++++++++ system-config/
2026-06-08 13:11:24.645298 | controller | cd+++++++++ system-config/libvirt/
2026-06-08 13:11:24.645333 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-06-08 13:11:24.645370 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-06-08 13:11:25.147573 | controller | changed: .d..t...... ./
2026-06-08 13:11:25.674713 | controller | changed: .d..t...... ./
2026-06-08 13:11:25.699388 | 
2026-06-08 13:11:25.699691 | TASK [Return artifact to Zuul]
2026-06-08 13:11:25.739779 | controller | ok
2026-06-08 13:11:25.743453 | 
2026-06-08 13:11:25.743612 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-06-08 13:11:25.743829 | 
2026-06-08 13:11:25.743891 | PLAY RECAP
2026-06-08 13:11:25.743969 | controller | ok: 19 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-06-08 13:11:25.744073 | 
2026-06-08 13:11:25.874454 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 13:11:25.875631 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 13:11:26.455390 | 
2026-06-08 13:11:26.455497 | PLAY [all]
2026-06-08 13:11:26.464971 | 
2026-06-08 13:11:26.465050 | TASK [include_role : fetch-output]
2026-06-08 13:11:26.506391 | controller | ok
2026-06-08 13:11:26.523970 | 
2026-06-08 13:11:26.524090 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 13:11:26.598961 | controller | skipping: Conditional result was False
2026-06-08 13:11:26.604705 | 
2026-06-08 13:11:26.604829 | TASK [fetch-output : Set log path for single node]
2026-06-08 13:11:26.644388 | controller | ok
2026-06-08 13:11:26.649267 | 
2026-06-08 13:11:26.649352 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 13:11:27.079789 | controller -> localhost | ok: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/logs"
2026-06-08 13:11:27.339426 | controller -> localhost | ok: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/artifacts"
2026-06-08 13:11:27.600352 | controller -> localhost | ok: "/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/docs"
2026-06-08 13:11:27.607036 | 
2026-06-08 13:11:27.607099 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 13:11:28.390254 | controller | ok
2026-06-08 13:11:28.390953 | controller | ok: All items complete
2026-06-08 13:11:28.391102 | 
2026-06-08 13:11:28.895249 | controller | ok
2026-06-08 13:11:29.428474 | controller | ok
2026-06-08 13:11:29.443197 | 
2026-06-08 13:11:29.443348 | TASK [include_role : fetch-output-openshift]
2026-06-08 13:11:29.458692 | controller | skipping: Conditional result was False
2026-06-08 13:11:29.463043 | 
2026-06-08 13:11:29.463105 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-06-08 13:11:29.907090 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.019544
2026-06-08 13:11:30.233662 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.013088
2026-06-08 13:11:30.256134 | 
2026-06-08 13:11:30.256403 | PLAY [all]
2026-06-08 13:11:30.266731 | 
2026-06-08 13:11:30.266866 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-06-08 13:11:30.735042 | controller | changed
2026-06-08 13:11:30.751269 | 
2026-06-08 13:11:30.751375 | PLAY RECAP
2026-06-08 13:11:30.751459 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-06-08 13:11:30.751501 | 
2026-06-08 13:11:30.858903 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 13:11:30.860708 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-06-08 13:11:31.499858 | 
2026-06-08 13:11:31.500069 | PLAY [localhost]
2026-06-08 13:11:31.510992 | 
2026-06-08 13:11:31.511087 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-06-08 13:11:31.903747 | localhost | changed
2026-06-08 13:11:31.916369 | 
2026-06-08 13:11:31.916588 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-06-08 13:11:31.947270 | localhost | ok
2026-06-08 13:11:31.955725 | 
2026-06-08 13:11:31.955817 | TASK [add-fileserver : Create SSH private key tempfile]
2026-06-08 13:11:32.449932 | localhost | changed
2026-06-08 13:11:32.460436 | 
2026-06-08 13:11:32.460661 | TASK [add-fileserver : Create SSH private key from secret]
2026-06-08 13:11:33.271801 | localhost | changed
2026-06-08 13:11:33.277410 | 
2026-06-08 13:11:33.277496 | TASK [add-fileserver : Add fileserver ssh key]
2026-06-08 13:11:33.741346 | localhost | Identity added: /var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/tmp/ansible._jebla7n (/var/lib/zuul/builds/4f0216a1de4d414d87eb5cbc8d9eea3b/work/tmp/ansible._jebla7n)
2026-06-08 13:11:33.741805 | localhost | ok: Runtime: 0:00:00.017880
2026-06-08 13:11:33.748912 | 
2026-06-08 13:11:33.749043 | TASK [add-fileserver : Remove SSH private key from disk]
2026-06-08 13:11:34.061730 | localhost | ok: Runtime: 0:00:00.009071
2026-06-08 13:11:34.065268 | 
2026-06-08 13:11:34.065329 | TASK [add-fileserver : Add fileserver to inventory]
2026-06-08 13:11:34.122380 | localhost | changed
2026-06-08 13:11:34.126634 | 
2026-06-08 13:11:34.126693 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-06-08 13:11:34.597210 | localhost | changed
2026-06-08 13:11:34.602072 | 
2026-06-08 13:11:34.602124 | PLAY [localhost]
2026-06-08 13:11:34.606145 | 
2026-06-08 13:11:34.606203 | TASK [Generate bulk log download script]
2026-06-08 13:11:34.625500 | localhost | ok
2026-06-08 13:11:34.640129 | 
2026-06-08 13:11:34.640210 | TASK [local-log-download : Check API endpoint is defined]
2026-06-08 13:11:34.691910 | localhost | ok: All assertions passed
2026-06-08 13:11:34.700700 | 
2026-06-08 13:11:34.700831 | TASK [local-log-download : Create download script]
2026-06-08 13:11:35.224918 | localhost -> localhost | changed
2026-06-08 13:11:35.258779 | 
2026-06-08 13:11:35.258896 | TASK [Register quick-download link]
2026-06-08 13:11:35.286230 | localhost | ok
2026-06-08 13:11:35.288283 | 
2026-06-08 13:11:35.288334 | PLAY [a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com]
2026-06-08 13:11:35.292909 | 
2026-06-08 13:11:35.292965 | TASK [Set zuul-log-path fact]
2026-06-08 13:11:35.318045 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 13:11:35.326310 | 
2026-06-08 13:11:35.326381 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 13:11:35.362094 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 13:11:35.364538 | 
2026-06-08 13:11:35.364601 | TASK [upload-logs : Create log directories]
2026-06-08 13:11:36.213879 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | changed
2026-06-08 13:11:36.218438 | 
2026-06-08 13:11:36.218630 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-06-08 13:11:36.522559 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com -> localhost | ok: Runtime: 0:00:00.005085
2026-06-08 13:11:36.528751 | 
2026-06-08 13:11:36.529016 | TASK [upload-logs : Upload logs to log server]
2026-06-08 13:11:38.633879 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | Output suppressed because no_log was given
2026-06-08 13:11:38.637173 | 
2026-06-08 13:11:38.637320 | LOOP [upload-logs : Compress console log and json output]