2026-06-08 14:57:30.895947 | Job console starting
2026-06-08 14:57:31.230724 | Updating git repos
2026-06-08 14:57:31.288970 | Cloning repos into workspace
2026-06-08 14:57:34.571239 | Restoring repo states
2026-06-08 14:57:34.589748 | Merging changes
2026-06-08 14:57:35.737869 | Checking out repos
2026-06-08 14:57:36.438679 | Preparing playbooks
2026-06-08 14:57:41.191481 | Running Ansible setup
2026-06-08 14:57:44.981089 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 14:57:45.618370 | 
2026-06-08 14:57:45.618510 | PLAY [localhost]
2026-06-08 14:57:45.626219 | 
2026-06-08 14:57:45.626286 | TASK [Gathering Facts]
2026-06-08 14:57:46.597654 | localhost | ok
2026-06-08 14:57:46.614199 | 
2026-06-08 14:57:46.614612 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-06-08 14:57:47.099660 | localhost -> localhost | changed
2026-06-08 14:57:47.108524 | 
2026-06-08 14:57:47.108659 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-06-08 14:57:48.147592 | localhost -> localhost | changed
2026-06-08 14:57:48.157419 | 
2026-06-08 14:57:48.157610 | TASK [Setup log path fact]
2026-06-08 14:57:48.178774 | localhost | ok
2026-06-08 14:57:48.191620 | 
2026-06-08 14:57:48.191730 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 14:57:48.231673 | localhost | ok
2026-06-08 14:57:48.239669 | 
2026-06-08 14:57:48.239779 | TASK [emit-job-header : Print job information]
2026-06-08 14:57:48.290821 | # Job Information
2026-06-08 14:57:48.291064 | Ansible Version: 2.16.18
2026-06-08 14:57:48.291115 | Job: cifmw-molecule-bm_sno
2026-06-08 14:57:48.291156 | Pipeline: github-check
2026-06-08 14:57:48.291193 | Executor: 38.102.83.51
2026-06-08 14:57:48.291228 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3971
2026-06-08 14:57:48.291265 | Log URL (when completed): https://gateway-cloud-softwarefactory.apps.ocp.cloud.ci.centos.org/logs/ded/rdoproject.org/ded8c15cec7848879ec1fd32ca9c20e5/
2026-06-08 14:57:48.291306 | Event ID: 331f6020-634a-11f1-8863-bb402e2269e5
2026-06-08 14:57:48.296943 | 
2026-06-08 14:57:48.297093 | LOOP [emit-job-header : Print node information]
2026-06-08 14:57:48.390811 | localhost | ok:
2026-06-08 14:57:48.391046 | localhost | # Node Information
2026-06-08 14:57:48.391103 | localhost | Inventory Hostname: controller
2026-06-08 14:57:48.391152 | localhost | Hostname: np0000067386
2026-06-08 14:57:48.391194 | localhost | Username: zuul
2026-06-08 14:57:48.391238 | localhost | Distro: CentOS 9
2026-06-08 14:57:48.391276 | localhost | Provider: vexxhost-nodepool-tripleo
2026-06-08 14:57:48.391314 | localhost | Region: RegionOne
2026-06-08 14:57:48.391388 | localhost | Label: cloud-centos-9-stream-tripleo
2026-06-08 14:57:48.391436 | localhost | Product Name: OpenStack Nova
2026-06-08 14:57:48.391473 | localhost | Interface IP: 38.102.83.66
2026-06-08 14:57:48.401429 | 
2026-06-08 14:57:48.401540 | PLAY [all]
2026-06-08 14:57:48.413388 | 
2026-06-08 14:57:48.413519 | TASK [Gather network facts]
2026-06-08 14:57:48.854765 | controller | ok
2026-06-08 14:57:48.866399 | 
2026-06-08 14:57:48.866518 | TASK [include_role : start-zuul-console]
2026-06-08 14:57:48.896571 | controller | ok
2026-06-08 14:57:48.916001 | 
2026-06-08 14:57:48.916099 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-06-08 14:57:49.414179 | controller | ok
2026-06-08 14:57:49.426950 | 
2026-06-08 14:57:49.427106 | TASK [include_role : add-build-sshkey]
2026-06-08 14:57:49.462702 | controller | ok
2026-06-08 14:57:49.486650 | 
2026-06-08 14:57:49.486837 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-06-08 14:57:49.838939 | controller -> localhost | ok
2026-06-08 14:57:49.848887 | 
2026-06-08 14:57:49.849126 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-06-08 14:57:49.886492 | controller | ok
2026-06-08 14:57:49.913704 | controller | included: /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-06-08 14:57:49.919649 | 
2026-06-08 14:57:49.919727 | TASK [add-build-sshkey : Create Temp SSH key]
2026-06-08 14:57:50.672164 | controller -> localhost | Generating public/private rsa key pair.
2026-06-08 14:57:50.672539 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/ded8c15cec7848879ec1fd32ca9c20e5_id_rsa
2026-06-08 14:57:50.672609 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/ded8c15cec7848879ec1fd32ca9c20e5_id_rsa.pub
2026-06-08 14:57:50.672659 | controller -> localhost | The key fingerprint is:
2026-06-08 14:57:50.672704 | controller -> localhost | SHA256:PNfrzXf3ie9/QDOxmyAcmAvLlaJX7LE9BAQnRqfO4tk zuul-build-sshkey
2026-06-08 14:57:50.672748 | controller -> localhost | The key's randomart image is:
2026-06-08 14:57:50.672789 | controller -> localhost | +---[RSA 3072]----+
2026-06-08 14:57:50.672829 | controller -> localhost | |     .=+==       |
2026-06-08 14:57:50.672870 | controller -> localhost | |     .o=O o   .  |
2026-06-08 14:57:50.672911 | controller -> localhost | |     o.B B .   o |
2026-06-08 14:57:50.672952 | controller -> localhost | |    .o+.+ =.. =  |
2026-06-08 14:57:50.672992 | controller -> localhost | |    ..o S .o.o = |
2026-06-08 14:57:50.673032 | controller -> localhost | |   . +   o   .+  |
2026-06-08 14:57:50.673070 | controller -> localhost | |    o E     .  . |
2026-06-08 14:57:50.673110 | controller -> localhost | |           . o. *|
2026-06-08 14:57:50.673149 | controller -> localhost | |            ..==O|
2026-06-08 14:57:50.673188 | controller -> localhost | +----[SHA256]-----+
2026-06-08 14:57:50.673301 | controller -> localhost | ok: Runtime: 0:00:00.185899
2026-06-08 14:57:50.681549 | 
2026-06-08 14:57:50.681690 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-06-08 14:57:50.724938 | controller | ok
2026-06-08 14:57:50.742060 | controller | included: /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-06-08 14:57:50.757078 | 
2026-06-08 14:57:50.757213 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-06-08 14:57:50.793101 | controller | skipping: Conditional result was False
2026-06-08 14:57:50.805023 | 
2026-06-08 14:57:50.805114 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-06-08 14:57:51.323870 | controller | changed
2026-06-08 14:57:51.331543 | 
2026-06-08 14:57:51.331670 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-06-08 14:57:51.609739 | controller | ok
2026-06-08 14:57:51.617095 | 
2026-06-08 14:57:51.617229 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-06-08 14:57:52.471187 | controller | changed
2026-06-08 14:57:52.478884 | 
2026-06-08 14:57:52.479099 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-06-08 14:57:53.270196 | controller | changed
2026-06-08 14:57:53.277874 | 
2026-06-08 14:57:53.278004 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-06-08 14:57:53.304489 | controller | skipping: Conditional result was False
2026-06-08 14:57:53.313301 | 
2026-06-08 14:57:53.313485 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-06-08 14:57:53.808648 | controller -> localhost | changed
2026-06-08 14:57:53.828887 | 
2026-06-08 14:57:53.829072 | TASK [add-build-sshkey : Add back temp key]
2026-06-08 14:57:54.206607 | controller -> localhost | Identity added: /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/ded8c15cec7848879ec1fd32ca9c20e5_id_rsa (zuul-build-sshkey)
2026-06-08 14:57:54.206939 | controller -> localhost | ok: Runtime: 0:00:00.017501
2026-06-08 14:57:54.214285 | 
2026-06-08 14:57:54.214441 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-06-08 14:57:54.632826 | controller | ok
2026-06-08 14:57:54.639500 | 
2026-06-08 14:57:54.639623 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-06-08 14:57:54.676952 | controller | skipping: Conditional result was False
2026-06-08 14:57:54.691786 | 
2026-06-08 14:57:54.691931 | TASK [include_role : validate-host]
2026-06-08 14:57:54.728687 | controller | ok
2026-06-08 14:57:54.768410 | 
2026-06-08 14:57:54.768828 | TASK [validate-host : Define zuul_info_dir fact]
2026-06-08 14:57:54.816876 | controller | ok
2026-06-08 14:57:54.824078 | 
2026-06-08 14:57:54.824203 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-06-08 14:57:55.135631 | controller -> localhost | ok
2026-06-08 14:57:55.146161 | 
2026-06-08 14:57:55.146290 | TASK [validate-host : Collect information about the host]
2026-06-08 14:57:55.902137 | controller | ok
2026-06-08 14:57:55.923647 | 
2026-06-08 14:57:55.923801 | TASK [validate-host : Sanitize hostname]
2026-06-08 14:57:56.000056 | controller | ok
2026-06-08 14:57:56.009434 | 
2026-06-08 14:57:56.009564 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-06-08 14:57:56.607414 | controller -> localhost | changed
2026-06-08 14:57:56.619929 | 
2026-06-08 14:57:56.620126 | TASK [validate-host : Collect information about zuul worker]
2026-06-08 14:57:57.101269 | controller | ok
2026-06-08 14:57:57.105431 | 
2026-06-08 14:57:57.105503 | TASK [validate-host : Write out all zuul information for each host]
2026-06-08 14:57:57.665079 | controller -> localhost | changed
2026-06-08 14:57:57.682451 | 
2026-06-08 14:57:57.682661 | TASK [include_role : prepare-workspace-openshift]
2026-06-08 14:57:57.722181 | controller | skipping: Conditional result was False
2026-06-08 14:57:57.730594 | 
2026-06-08 14:57:57.730762 | TASK [include_role : remove-zuul-sshkey]
2026-06-08 14:57:57.778234 | controller | skipping: Conditional result was False
2026-06-08 14:57:57.789646 | 
2026-06-08 14:57:57.789899 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-06-08 14:57:58.063369 | controller | ok: "logs"
2026-06-08 14:57:58.063776 | controller | ok: All items complete
2026-06-08 14:57:58.063813 | 
2026-06-08 14:57:58.284185 | controller | ok: "artifacts"
2026-06-08 14:57:58.523868 | controller | ok: "docs"
2026-06-08 14:57:58.539078 | 
2026-06-08 14:57:58.539316 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-06-08 14:57:58.785310 | controller | changed: "logs"
2026-06-08 14:57:59.025805 | controller | changed: "artifacts"
2026-06-08 14:57:59.249411 | controller | changed: "docs"
2026-06-08 14:57:59.261993 | 
2026-06-08 14:57:59.262202 | PLAY RECAP
2026-06-08 14:57:59.262289 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 14:57:59.262342 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 14:57:59.262422 | 
2026-06-08 14:57:59.421391 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 14:57:59.423706 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 14:58:00.156527 | 
2026-06-08 14:58:00.156680 | PLAY [all]
2026-06-08 14:58:00.167769 | 
2026-06-08 14:58:00.167860 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 14:58:00.261125 | controller | ok
2026-06-08 14:58:00.269685 | 
2026-06-08 14:58:00.269856 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 14:58:00.745770 | controller | changed
2026-06-08 14:58:00.755173 | 
2026-06-08 14:58:00.755321 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 14:58:01.978961 | controller | changed
2026-06-08 14:58:01.987166 | 
2026-06-08 14:58:01.987236 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-06-08 14:58:02.500140 | controller | changed:
2026-06-08 14:58:02.500579 | controller | {
2026-06-08 14:58:02.500622 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-06-08 14:58:02.500666 | controller | }
2026-06-08 14:58:02.741582 | controller | changed:
2026-06-08 14:58:02.741740 | controller | {
2026-06-08 14:58:02.741775 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-06-08 14:58:02.741803 | controller | }
2026-06-08 14:58:03.008937 | controller | changed:
2026-06-08 14:58:03.009128 | controller | {
2026-06-08 14:58:03.009183 | 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 14:58:03.009224 | controller | }
2026-06-08 14:58:03.244740 | controller | changed:
2026-06-08 14:58:03.244891 | controller | {
2026-06-08 14:58:03.244926 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-06-08 14:58:03.244953 | controller | }
2026-06-08 14:58:03.514466 | controller | changed:
2026-06-08 14:58:03.514723 | controller | {
2026-06-08 14:58:03.514807 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-06-08 14:58:03.514875 | controller | }
2026-06-08 14:58:03.748918 | controller | changed:
2026-06-08 14:58:03.749262 | controller | {
2026-06-08 14:58:03.749534 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-06-08 14:58:03.749639 | controller | }
2026-06-08 14:58:04.009335 | controller | changed:
2026-06-08 14:58:04.009606 | controller | {
2026-06-08 14:58:04.009660 | 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 14:58:04.009703 | controller | }
2026-06-08 14:58:04.301015 | controller | changed:
2026-06-08 14:58:04.301239 | controller | {
2026-06-08 14:58:04.301301 | 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 14:58:04.301485 | controller | }
2026-06-08 14:58:04.551640 | controller | changed:
2026-06-08 14:58:04.551833 | controller | {
2026-06-08 14:58:04.551883 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-06-08 14:58:04.551922 | controller | }
2026-06-08 14:58:04.818765 | controller | changed:
2026-06-08 14:58:04.818916 | controller | {
2026-06-08 14:58:04.818943 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-06-08 14:58:04.818961 | controller | }
2026-06-08 14:58:05.092081 | controller | changed:
2026-06-08 14:58:05.092223 | controller | {
2026-06-08 14:58:05.092253 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-06-08 14:58:05.092324 | controller | }
2026-06-08 14:58:05.364610 | controller | changed:
2026-06-08 14:58:05.364760 | controller | {
2026-06-08 14:58:05.364783 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-06-08 14:58:05.364803 | controller | }
2026-06-08 14:58:05.653412 | controller | changed:
2026-06-08 14:58:05.653546 | controller | {
2026-06-08 14:58:05.653569 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-06-08 14:58:05.653587 | controller | }
2026-06-08 14:58:05.946049 | controller | changed:
2026-06-08 14:58:05.946239 | controller | {
2026-06-08 14:58:05.946291 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-06-08 14:58:05.946332 | controller | }
2026-06-08 14:58:06.165520 | controller | changed:
2026-06-08 14:58:06.165785 | controller | {
2026-06-08 14:58:06.165847 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-06-08 14:58:06.165890 | controller | }
2026-06-08 14:58:06.403918 | controller | changed:
2026-06-08 14:58:06.404083 | controller | {
2026-06-08 14:58:06.404134 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-06-08 14:58:06.404174 | controller | }
2026-06-08 14:58:06.640501 | controller | changed:
2026-06-08 14:58:06.640691 | controller | {
2026-06-08 14:58:06.640744 | 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 14:58:06.640787 | controller | }
2026-06-08 14:58:06.927258 | controller | changed:
2026-06-08 14:58:06.927485 | controller | {
2026-06-08 14:58:06.927539 | 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 14:58:06.927607 | controller | }
2026-06-08 14:58:07.185852 | controller | changed:
2026-06-08 14:58:07.186035 | controller | {
2026-06-08 14:58:07.186088 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-06-08 14:58:07.186129 | controller | }
2026-06-08 14:58:07.415267 | controller | changed:
2026-06-08 14:58:07.415486 | controller | {
2026-06-08 14:58:07.415540 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-06-08 14:58:07.415584 | controller | }
2026-06-08 14:58:07.672615 | controller | changed:
2026-06-08 14:58:07.672803 | controller | {
2026-06-08 14:58:07.672852 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-06-08 14:58:07.672891 | controller | }
2026-06-08 14:58:07.912517 | controller | changed:
2026-06-08 14:58:07.912806 | controller | {
2026-06-08 14:58:07.912869 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-06-08 14:58:07.912913 | controller | }
2026-06-08 14:58:08.196992 | controller | changed:
2026-06-08 14:58:08.197248 | controller | {
2026-06-08 14:58:08.197298 | 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 14:58:08.197332 | controller | }
2026-06-08 14:58:08.468798 | controller | changed:
2026-06-08 14:58:08.468991 | controller | {
2026-06-08 14:58:08.469045 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-06-08 14:58:08.469089 | controller | }
2026-06-08 14:58:08.738325 | controller | changed:
2026-06-08 14:58:08.738574 | controller | {
2026-06-08 14:58:08.738638 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-06-08 14:58:08.738688 | controller | }
2026-06-08 14:58:08.981834 | controller | changed:
2026-06-08 14:58:08.982281 | controller | {
2026-06-08 14:58:08.982342 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-06-08 14:58:08.982436 | controller | }
2026-06-08 14:58:09.010553 | 
2026-06-08 14:58:09.010706 | TASK [Set timezone to UTC]
2026-06-08 14:58:09.543911 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-06-08 14:58:09.551683 | 
2026-06-08 14:58:09.551818 | TASK [Create nodepool directory]
2026-06-08 14:58:09.841078 | controller | changed
2026-06-08 14:58:09.851986 | 
2026-06-08 14:58:09.852115 | TASK [Create nodepool sub_nodes file]
2026-06-08 14:58:10.664031 | controller | changed
2026-06-08 14:58:10.675267 | 
2026-06-08 14:58:10.675532 | TASK [Create nodepool sub_nodes_private file]
2026-06-08 14:58:11.517111 | controller | changed
2026-06-08 14:58:11.525957 | 
2026-06-08 14:58:11.526209 | LOOP [Populate nodepool sub_nodes file]
2026-06-08 14:58:11.569717 | 
2026-06-08 14:58:11.569956 | LOOP [Populate nodepool sub_nodes_private file]
2026-06-08 14:58:11.611273 | 
2026-06-08 14:58:11.611519 | TASK [Create nodepool primary file]
2026-06-08 14:58:11.636670 | controller | skipping: Conditional result was False
2026-06-08 14:58:11.641521 | 
2026-06-08 14:58:11.641642 | TASK [Create nodepool node_private for this node]
2026-06-08 14:58:12.493153 | controller | changed
2026-06-08 14:58:12.504047 | 
2026-06-08 14:58:12.504191 | LOOP [Copy ssh keys to nodepool directory]
2026-06-08 14:58:13.033047 | controller | ok: Item: id_rsa Runtime: 0:00:00.029165
2026-06-08 14:58:13.033419 | 
2026-06-08 14:58:13.379127 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.010899
2026-06-08 14:58:13.398224 | 
2026-06-08 14:58:13.398515 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-06-08 14:58:14.350083 | controller | changed
2026-06-08 14:58:14.357562 | 
2026-06-08 14:58:14.357686 | TASK [Validate sudoers config after edits]
2026-06-08 14:58:14.701898 | controller | /etc/sudoers: parsed OK
2026-06-08 14:58:14.702008 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-06-08 14:58:14.702022 | controller | /etc/sudoers.d/zuul: parsed OK
2026-06-08 14:58:14.702031 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-06-08 14:58:14.907394 | controller | ok: Runtime: 0:00:00.008583
2026-06-08 14:58:14.916167 | 
2026-06-08 14:58:14.916294 | TASK [Show the environment passed in to job shell scripts]
2026-06-08 14:58:15.181203 | controller | SHELL=/bin/bash
2026-06-08 14:58:15.181359 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-06-08 14:58:15.181377 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-06-08 14:58:15.181391 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/71/3971/997d53f39a54c49e1d160255f607e36aac88c938
2026-06-08 14:58:15.181400 | controller | PWD=/home/zuul
2026-06-08 14:58:15.181409 | controller | ZUUL_PIPELINE=github-check
2026-06-08 14:58:15.181421 | controller | LOGNAME=zuul
2026-06-08 14:58:15.181429 | controller | XDG_SESSION_TYPE=tty
2026-06-08 14:58:15.181436 | controller | _=/usr/bin/env
2026-06-08 14:58:15.181447 | controller | MOTD_SHOWN=pam
2026-06-08 14:58:15.181455 | controller | HOME=/home/zuul
2026-06-08 14:58:15.181462 | controller | LANG=en_US.UTF-8
2026-06-08 14:58:15.181471 | controller | SSH_CONNECTION=38.102.83.51 43374 38.102.83.66 22
2026-06-08 14:58:15.181481 | 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 14:58:15.181490 | controller | ZUUL_CHANGE_IDS=3971,997d53f39a54c49e1d160255f607e36aac88c938
2026-06-08 14:58:15.181498 | controller | WORKSPACE=/home/zuul/workspace
2026-06-08 14:58:15.181506 | controller | XDG_SESSION_CLASS=user
2026-06-08 14:58:15.181513 | controller | SELINUX_ROLE_REQUESTED=
2026-06-08 14:58:15.181521 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-06-08 14:58:15.181529 | controller | USER=zuul
2026-06-08 14:58:15.181537 | controller | ZUUL_VOTING=True
2026-06-08 14:58:15.181545 | controller | BUILD_TIMEOUT=1800000
2026-06-08 14:58:15.181552 | controller | SELINUX_USE_CURRENT_RANGE=
2026-06-08 14:58:15.181560 | controller | SHLVL=1
2026-06-08 14:58:15.181568 | controller | ZUUL_PATCHSET=997d53f39a54c49e1d160255f607e36aac88c938
2026-06-08 14:58:15.181575 | controller | XDG_SESSION_ID=1
2026-06-08 14:58:15.181583 | controller | ZUUL_BRANCH=main
2026-06-08 14:58:15.181590 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-06-08 14:58:15.181598 | controller | SSH_CLIENT=38.102.83.51 43374 22
2026-06-08 14:58:15.181614 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-06-08 14:58:15.181623 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-06-08 14:58:15.181631 | controller | which_declare=declare -f
2026-06-08 14:58:15.181639 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2026-06-08 14:58:15.181647 | controller | SELINUX_LEVEL_REQUESTED=
2026-06-08 14:58:15.181654 | controller | ZUUL_CHANGE=3971
2026-06-08 14:58:15.181662 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-06-08 14:58:15.181670 | controller | ZUUL_UUID=ded8c15cec7848879ec1fd32ca9c20e5
2026-06-08 14:58:15.181678 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-06-08 14:58:15.181686 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-06-08 14:58:15.181695 | controller | }
2026-06-08 14:58:15.462811 | controller | ok: Runtime: 0:00:00.007365
2026-06-08 14:58:15.482071 | 
2026-06-08 14:58:15.482247 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-06-08 14:58:15.509675 | controller | skipping: Conditional result was False
2026-06-08 14:58:15.518375 | 
2026-06-08 14:58:15.518507 | TASK [Symlink /home/zuul-worker/workspace]
2026-06-08 14:58:16.057907 | controller | skipping: Conditional result was False
2026-06-08 14:58:16.067295 | 
2026-06-08 14:58:16.067471 | TASK [Ensure legacy workspace directory]
2026-06-08 14:58:16.306223 | controller | changed
2026-06-08 14:58:16.308833 | 
2026-06-08 14:58:16.308929 | PLAY RECAP
2026-06-08 14:58:16.309009 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 14:58:16.309052 | 
2026-06-08 14:58:16.459773 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 14:58:16.463958 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 14:58:17.085214 | 
2026-06-08 14:58:17.085366 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-06-08 14:58:17.096462 | 
2026-06-08 14:58:17.096535 | TASK [Create zuul-output directory]
2026-06-08 14:58:17.512931 | controller | changed
2026-06-08 14:58:17.520808 | 
2026-06-08 14:58:17.520951 | TASK [Slurp Zuul inventory test]
2026-06-08 14:58:18.003604 | controller -> localhost | ok
2026-06-08 14:58:18.014836 | 
2026-06-08 14:58:18.014979 | TASK [Save zuul inventory]
2026-06-08 14:58:19.157361 | controller | changed
2026-06-08 14:58:19.160864 | 
2026-06-08 14:58:19.160933 | TASK [Save zuul vars without the change_message]
2026-06-08 14:58:20.086340 | controller | changed
2026-06-08 14:58:20.089705 | 
2026-06-08 14:58:20.089822 | PLAY RECAP
2026-06-08 14:58:20.089925 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 14:58:20.089981 | 
2026-06-08 14:58:20.235927 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 14:58:20.238100 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 14:58:20.889881 | 
2026-06-08 14:58:20.890021 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-06-08 14:58:20.901462 | 
2026-06-08 14:58:20.901545 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-06-08 14:58:20.921742 | controller | ok
2026-06-08 14:58:20.935654 | 
2026-06-08 14:58:20.935729 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 14:58:20.980281 | controller | skipping: Conditional result was False
2026-06-08 14:58:20.986864 | 
2026-06-08 14:58:20.986961 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 14:58:21.427691 | controller | ok
2026-06-08 14:58:21.437552 | 
2026-06-08 14:58:21.437705 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 14:58:22.437594 | controller | ok
2026-06-08 14:58:22.457960 | 
2026-06-08 14:58:22.458321 | TASK [Prepare workspace]
2026-06-08 14:58:22.481693 | controller | ok
2026-06-08 14:58:22.508242 | 
2026-06-08 14:58:22.508439 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-06-08 14:58:22.916270 | controller | ok
2026-06-08 14:58:22.929708 | 
2026-06-08 14:58:22.929894 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-06-08 14:58:25.026842 | controller | Output suppressed because no_log was given
2026-06-08 14:58:25.033571 | 
2026-06-08 14:58:25.033655 | LOOP [Create zuul-output directory]
2026-06-08 14:58:25.303251 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-06-08 14:58:29.980641 | controller | ok: "/home/zuul/zuul-output/logs"
2026-06-08 14:58:29.993991 | 
2026-06-08 14:58:29.994084 | TASK [Install required packages]
2026-06-08 14:59:17.504415 | controller | changed
2026-06-08 14:59:17.516672 | 
2026-06-08 14:59:17.516835 | TASK [Install venv]
2026-06-08 15:00:34.620927 | controller | changed
2026-06-08 15:00:34.640131 | 
2026-06-08 15:00:34.640438 | PLAY RECAP
2026-06-08 15:00:34.640566 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 15:00:34.640617 | 
2026-06-08 15:00:34.807428 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 15:00:34.811240 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 15:00:35.531157 | 
2026-06-08 15:00:35.531302 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-06-08 15:00:35.542585 | 
2026-06-08 15:00:35.542657 | TASK [Gather required facts]
2026-06-08 15:00:36.147224 | controller | ok
2026-06-08 15:00:36.156084 | 
2026-06-08 15:00:36.156295 | TASK [Load environment var if instructed to]
2026-06-08 15:00:36.194052 | controller | skipping: Conditional result was False
2026-06-08 15:00:36.203023 | 
2026-06-08 15:00:36.203287 | TASK [Ensure group_vars dir exists]
2026-06-08 15:00:36.636795 | controller | ok
2026-06-08 15:00:36.646422 | 
2026-06-08 15:00:36.646636 | TASK [Print related variables]
2026-06-08 15:00:36.696762 | controller | ok:
2026-06-08 15:00:36.697070 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-06-08 15:00:36.697128 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno
2026-06-08 15:00:36.708913 | 
2026-06-08 15:00:36.709068 | TASK [Run molecule]
2026-06-08 15:00:38.005376 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-06-08 15:00:38.090483 | controller | INFO     Running bm_redfish > prepare
2026-06-08 15:00:39.001595 | controller |
2026-06-08 15:00:39.001734 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-06-08 15:00:39.002116 | controller |
2026-06-08 15:00:39.002392 | controller | TASK [Create mock server directory] ********************************************
2026-06-08 15:00:39.003519 | controller | Monday 08 June 2026  15:00:38 +0000 (0:00:00.024)       0:00:00.024 ***********
2026-06-08 15:00:39.478969 | controller | changed: [instance]
2026-06-08 15:00:39.479038 | controller |
2026-06-08 15:00:39.479207 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-06-08 15:00:39.479344 | controller | Monday 08 June 2026  15:00:39 +0000 (0:00:00.478)       0:00:00.502 ***********
2026-06-08 15:00:40.029244 | controller | changed: [instance]
2026-06-08 15:00:40.029353 | controller |
2026-06-08 15:00:40.029403 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-06-08 15:00:40.029488 | controller | Monday 08 June 2026  15:00:40 +0000 (0:00:00.549)       0:00:01.052 ***********
2026-06-08 15:00:40.725811 | controller | changed: [instance]
2026-06-08 15:00:40.725921 | controller |
2026-06-08 15:00:40.726188 | controller | TASK [Start mock iDRAC server] *************************************************
2026-06-08 15:00:40.726378 | controller | Monday 08 June 2026  15:00:40 +0000 (0:00:00.696)       0:00:01.749 ***********
2026-06-08 15:00:40.939397 | controller | changed: [instance]
2026-06-08 15:00:40.939456 | controller |
2026-06-08 15:00:40.939556 | controller | TASK [Record mock server PID] **************************************************
2026-06-08 15:00:40.939662 | controller | Monday 08 June 2026  15:00:40 +0000 (0:00:00.214)       0:00:01.963 ***********
2026-06-08 15:00:41.231486 | controller | ok: [instance]
2026-06-08 15:00:41.231987 | controller |
2026-06-08 15:00:41.232055 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-06-08 15:00:41.232064 | controller | Monday 08 June 2026  15:00:41 +0000 (0:00:00.291)       0:00:02.254 ***********
2026-06-08 15:00:41.796138 | controller | ok: [instance]
2026-06-08 15:00:41.796176 | controller |
2026-06-08 15:00:41.797314 | controller | PLAY RECAP *********************************************************************
2026-06-08 15:00:41.797367 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 15:00:41.797373 | controller |
2026-06-08 15:00:41.797379 | controller | Monday 08 June 2026  15:00:41 +0000 (0:00:00.565)       0:00:02.820 ***********
2026-06-08 15:00:41.797384 | controller | ===============================================================================
2026-06-08 15:00:41.797388 | controller | Copy mock iDRAC server script ------------------------------------------- 0.70s
2026-06-08 15:00:41.797392 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.57s
2026-06-08 15:00:41.797395 | controller | Generate self-signed TLS certificate ------------------------------------ 0.55s
2026-06-08 15:00:41.797399 | controller | Create mock server directory -------------------------------------------- 0.48s
2026-06-08 15:00:41.797403 | controller | Record mock server PID -------------------------------------------------- 0.29s
2026-06-08 15:00:41.797407 | controller | Start mock iDRAC server ------------------------------------------------- 0.21s
2026-06-08 15:00:41.881320 | controller | INFO     Running bm_redfish > converge
2026-06-08 15:00:42.364524 | controller |
2026-06-08 15:00:42.364873 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-06-08 15:00:42.365095 | controller |
2026-06-08 15:00:42.365294 | controller | TASK [Test bm_power_off] *******************************************************
2026-06-08 15:00:42.365510 | controller | Monday 08 June 2026  15:00:42 +0000 (0:00:00.043)       0:00:00.043 ***********
2026-06-08 15:00:42.386300 | 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 15:00:42.386547 | controller |
2026-06-08 15:00:42.386802 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 15:00:42.387087 | controller | Monday 08 June 2026  15:00:42 +0000 (0:00:00.022)       0:00:00.066 ***********
2026-06-08 15:00:42.939869 | controller | ok: [instance]
2026-06-08 15:00:42.939922 | controller |
2026-06-08 15:00:42.939949 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 15:00:42.939957 | controller | Monday 08 June 2026  15:00:42 +0000 (0:00:00.551)       0:00:00.618 ***********
2026-06-08 15:00:42.985078 | controller |
2026-06-08 15:00:42.985147 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:42.985152 | controller | Monday 08 June 2026  15:00:42 +0000 (0:00:00.045)       0:00:00.663 ***********
2026-06-08 15:00:43.457157 | controller | ok: [instance]
2026-06-08 15:00:43.457212 | controller |
2026-06-08 15:00:43.457219 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 15:00:43.457226 | controller | Monday 08 June 2026  15:00:43 +0000 (0:00:00.472)       0:00:01.135 ***********
2026-06-08 15:00:43.479130 | controller | skipping: [instance]
2026-06-08 15:00:43.479182 | controller |
2026-06-08 15:00:43.479195 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 15:00:43.479205 | controller | Monday 08 June 2026  15:00:43 +0000 (0:00:00.022)       0:00:01.158 ***********
2026-06-08 15:00:43.502898 | controller | skipping: [instance]
2026-06-08 15:00:43.502982 | controller |
2026-06-08 15:00:43.503141 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-06-08 15:00:43.503290 | controller | Monday 08 June 2026  15:00:43 +0000 (0:00:00.024)       0:00:01.182 ***********
2026-06-08 15:00:43.865055 | controller | ok: [instance]
2026-06-08 15:00:43.865104 | controller |
2026-06-08 15:00:43.865110 | controller | TASK [Assert host is still Off] ************************************************
2026-06-08 15:00:43.865117 | controller | Monday 08 June 2026  15:00:43 +0000 (0:00:00.361)       0:00:01.544 ***********
2026-06-08 15:00:43.888821 | controller | ok: [instance] => {
2026-06-08 15:00:43.888872 | controller |     "changed": false,
2026-06-08 15:00:43.888878 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:43.888885 | controller | }
2026-06-08 15:00:43.888891 | controller |
2026-06-08 15:00:43.888896 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 15:00:43.888903 | controller | Monday 08 June 2026  15:00:43 +0000 (0:00:00.023)       0:00:01.567 ***********
2026-06-08 15:00:44.258179 | controller | ok: [instance]
2026-06-08 15:00:44.258237 | controller |
2026-06-08 15:00:44.258250 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 15:00:44.258262 | controller | Monday 08 June 2026  15:00:44 +0000 (0:00:00.369)       0:00:01.937 ***********
2026-06-08 15:00:44.293989 | controller |
2026-06-08 15:00:44.294115 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:44.294262 | controller | Monday 08 June 2026  15:00:44 +0000 (0:00:00.036)       0:00:01.973 ***********
2026-06-08 15:00:44.690968 | controller | ok: [instance]
2026-06-08 15:00:44.691033 | controller |
2026-06-08 15:00:44.691050 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 15:00:44.691063 | controller | Monday 08 June 2026  15:00:44 +0000 (0:00:00.396)       0:00:02.369 ***********
2026-06-08 15:00:45.099802 | controller | ok: [instance]
2026-06-08 15:00:45.099842 | controller |
2026-06-08 15:00:45.099852 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 15:00:45.099861 | controller | Monday 08 June 2026  15:00:45 +0000 (0:00:00.408)       0:00:02.778 ***********
2026-06-08 15:00:45.504865 | controller | ok: [instance]
2026-06-08 15:00:45.504900 | controller |
2026-06-08 15:00:45.504907 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-06-08 15:00:45.504959 | controller | Monday 08 June 2026  15:00:45 +0000 (0:00:00.405)       0:00:03.184 ***********
2026-06-08 15:00:45.834131 | controller | ok: [instance]
2026-06-08 15:00:45.834176 | controller |
2026-06-08 15:00:45.834187 | controller | TASK [Assert host is now Off] **************************************************
2026-06-08 15:00:45.834196 | controller | Monday 08 June 2026  15:00:45 +0000 (0:00:00.328)       0:00:03.512 ***********
2026-06-08 15:00:45.867240 | controller | ok: [instance] => {
2026-06-08 15:00:45.867281 | controller |     "changed": false,
2026-06-08 15:00:45.868185 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:45.868248 | controller | }
2026-06-08 15:00:45.868260 | controller |
2026-06-08 15:00:45.868269 | controller | TASK [Test bm_power_on] ********************************************************
2026-06-08 15:00:45.868278 | controller | Monday 08 June 2026  15:00:45 +0000 (0:00:00.033)       0:00:03.546 ***********
2026-06-08 15:00:45.915140 | 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 15:00:45.915180 | controller |
2026-06-08 15:00:45.915193 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 15:00:45.915352 | controller | Monday 08 June 2026  15:00:45 +0000 (0:00:00.048)       0:00:03.594 ***********
2026-06-08 15:00:46.276062 | controller | ok: [instance]
2026-06-08 15:00:46.276105 | controller |
2026-06-08 15:00:46.276152 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 15:00:46.276301 | controller | Monday 08 June 2026  15:00:46 +0000 (0:00:00.360)       0:00:03.955 ***********
2026-06-08 15:00:46.310814 | controller |
2026-06-08 15:00:46.310879 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:46.310887 | controller | Monday 08 June 2026  15:00:46 +0000 (0:00:00.034)       0:00:03.990 ***********
2026-06-08 15:00:46.678144 | controller | ok: [instance]
2026-06-08 15:00:46.678187 | controller |
2026-06-08 15:00:46.678639 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 15:00:46.678686 | controller | Monday 08 June 2026  15:00:46 +0000 (0:00:00.366)       0:00:04.357 ***********
2026-06-08 15:00:46.700063 | controller | skipping: [instance]
2026-06-08 15:00:46.700083 | controller |
2026-06-08 15:00:46.700531 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 15:00:46.700558 | controller | Monday 08 June 2026  15:00:46 +0000 (0:00:00.022)       0:00:04.379 ***********
2026-06-08 15:00:47.120163 | controller | ok: [instance]
2026-06-08 15:00:47.120213 | controller |
2026-06-08 15:00:47.120223 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 15:00:47.120238 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.419)       0:00:04.798 ***********
2026-06-08 15:00:47.166091 | controller | ok: [instance] => {
2026-06-08 15:00:47.166118 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 15:00:47.166123 | controller | }
2026-06-08 15:00:47.166127 | controller |
2026-06-08 15:00:47.166299 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-06-08 15:00:47.166331 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.046)       0:00:04.845 ***********
2026-06-08 15:00:47.504113 | controller | ok: [instance]
2026-06-08 15:00:47.504165 | controller |
2026-06-08 15:00:47.504179 | controller | TASK [Assert host is still On with POST complete] ******************************
2026-06-08 15:00:47.504406 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.337)       0:00:05.183 ***********
2026-06-08 15:00:47.538073 | controller | ok: [instance] => {
2026-06-08 15:00:47.538107 | controller |     "changed": false,
2026-06-08 15:00:47.538111 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:47.538116 | controller | }
2026-06-08 15:00:47.538733 | controller |
2026-06-08 15:00:47.538766 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 15:00:47.538780 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.034)       0:00:05.217 ***********
2026-06-08 15:00:47.921169 | controller | ok: [instance]
2026-06-08 15:00:47.921209 | controller |
2026-06-08 15:00:47.921553 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 15:00:47.921599 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.383)       0:00:05.601 ***********
2026-06-08 15:00:47.951676 | controller |
2026-06-08 15:00:47.951737 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:47.951746 | controller | Monday 08 June 2026  15:00:47 +0000 (0:00:00.029)       0:00:05.630 ***********
2026-06-08 15:00:48.289265 | controller | ok: [instance]
2026-06-08 15:00:48.289339 | controller |
2026-06-08 15:00:48.289346 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 15:00:48.289352 | controller | Monday 08 June 2026  15:00:48 +0000 (0:00:00.337)       0:00:05.968 ***********
2026-06-08 15:00:48.677615 | controller | ok: [instance]
2026-06-08 15:00:48.677659 | controller |
2026-06-08 15:00:48.677665 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 15:00:48.677670 | controller | Monday 08 June 2026  15:00:48 +0000 (0:00:00.388)       0:00:06.356 ***********
2026-06-08 15:00:49.067203 | controller | ok: [instance]
2026-06-08 15:00:49.067247 | controller |
2026-06-08 15:00:49.067254 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 15:00:49.067259 | controller | Monday 08 June 2026  15:00:49 +0000 (0:00:00.389)       0:00:06.746 ***********
2026-06-08 15:00:49.112885 | controller | ok: [instance] => {
2026-06-08 15:00:49.112932 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 15:00:49.112939 | controller | }
2026-06-08 15:00:49.112944 | controller |
2026-06-08 15:00:49.112948 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-06-08 15:00:49.112966 | controller | Monday 08 June 2026  15:00:49 +0000 (0:00:00.045)       0:00:06.791 ***********
2026-06-08 15:00:49.539192 | controller | ok: [instance]
2026-06-08 15:00:49.539234 | controller |
2026-06-08 15:00:49.539245 | controller | TASK [Assert host is now On with POST complete] ********************************
2026-06-08 15:00:49.539260 | controller | Monday 08 June 2026  15:00:49 +0000 (0:00:00.426)       0:00:07.218 ***********
2026-06-08 15:00:49.567151 | controller | ok: [instance] => {
2026-06-08 15:00:49.567186 | controller |     "changed": false,
2026-06-08 15:00:49.567196 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:49.567205 | controller | }
2026-06-08 15:00:49.567213 | controller |
2026-06-08 15:00:49.567430 | controller | TASK [Reset mock to power Off without PostState support] ***********************
2026-06-08 15:00:49.567464 | controller | Monday 08 June 2026  15:00:49 +0000 (0:00:00.028)       0:00:07.246 ***********
2026-06-08 15:00:49.981002 | controller | ok: [instance]
2026-06-08 15:00:49.981038 | controller |
2026-06-08 15:00:49.981045 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 15:00:49.981051 | controller | Monday 08 June 2026  15:00:49 +0000 (0:00:00.414)       0:00:07.660 ***********
2026-06-08 15:00:50.010120 | controller |
2026-06-08 15:00:50.010353 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:50.010386 | controller | Monday 08 June 2026  15:00:50 +0000 (0:00:00.029)       0:00:07.690 ***********
2026-06-08 15:00:50.371917 | controller | ok: [instance]
2026-06-08 15:00:50.372132 | controller |
2026-06-08 15:00:50.372283 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 15:00:50.372464 | controller | Monday 08 June 2026  15:00:50 +0000 (0:00:00.361)       0:00:08.051 ***********
2026-06-08 15:00:50.742928 | controller | ok: [instance]
2026-06-08 15:00:50.743135 | controller |
2026-06-08 15:00:50.743269 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 15:00:50.743398 | controller | Monday 08 June 2026  15:00:50 +0000 (0:00:00.370)       0:00:08.422 ***********
2026-06-08 15:00:51.118435 | controller | ok: [instance]
2026-06-08 15:00:51.118611 | controller |
2026-06-08 15:00:51.118745 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 15:00:51.118880 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.375)       0:00:08.798 ***********
2026-06-08 15:00:51.156408 | controller | ok: [instance] => {
2026-06-08 15:00:51.156549 | controller |     "msg": "POST state: not supported by firmware, used PowerState=On"
2026-06-08 15:00:51.156680 | controller | }
2026-06-08 15:00:51.156798 | controller |
2026-06-08 15:00:51.156930 | controller | TASK [Query mock state after power_on (no PostState)] **************************
2026-06-08 15:00:51.157077 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.038)       0:00:08.836 ***********
2026-06-08 15:00:51.528899 | controller | ok: [instance]
2026-06-08 15:00:51.529295 | controller |
2026-06-08 15:00:51.529650 | controller | TASK [Assert host is On (PostState stays null)] ********************************
2026-06-08 15:00:51.530018 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.371)       0:00:09.207 ***********
2026-06-08 15:00:51.559405 | controller | ok: [instance] => {
2026-06-08 15:00:51.559715 | controller |     "changed": false,
2026-06-08 15:00:51.560044 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:51.560425 | controller | }
2026-06-08 15:00:51.560715 | controller |
2026-06-08 15:00:51.561028 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-06-08 15:00:51.561307 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.031)       0:00:09.239 ***********
2026-06-08 15:00:51.606026 | 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 15:00:51.606274 | controller |
2026-06-08 15:00:51.606466 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-06-08 15:00:51.606643 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.046)       0:00:09.285 ***********
2026-06-08 15:00:51.958428 | controller | ok: [instance]
2026-06-08 15:00:51.958766 | controller |
2026-06-08 15:00:51.959143 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-06-08 15:00:51.959447 | controller | Monday 08 June 2026  15:00:51 +0000 (0:00:00.352)       0:00:09.637 ***********
2026-06-08 15:00:52.003123 | controller |
2026-06-08 15:00:52.003318 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 15:00:52.003580 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.044)       0:00:09.682 ***********
2026-06-08 15:00:52.380837 | controller | ok: [instance]
2026-06-08 15:00:52.380984 | controller |
2026-06-08 15:00:52.381120 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 15:00:52.381226 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.378)       0:00:10.060 ***********
2026-06-08 15:00:52.412627 | controller | ok: [instance]
2026-06-08 15:00:52.412790 | controller |
2026-06-08 15:00:52.412910 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 15:00:52.413049 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.031)       0:00:10.092 ***********
2026-06-08 15:00:52.447187 | controller | skipping: [instance]
2026-06-08 15:00:52.447247 | controller |
2026-06-08 15:00:52.447351 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-06-08 15:00:52.447460 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.034)       0:00:10.127 ***********
2026-06-08 15:00:52.478901 | controller | ok: [instance] => {
2026-06-08 15:00:52.479048 | controller |     "changed": false,
2026-06-08 15:00:52.479196 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:52.479333 | controller | }
2026-06-08 15:00:52.479470 | controller |
2026-06-08 15:00:52.479623 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 15:00:52.479766 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.031)       0:00:10.158 ***********
2026-06-08 15:00:52.854869 | controller | ok: [instance]
2026-06-08 15:00:52.855046 | controller |
2026-06-08 15:00:52.855217 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-06-08 15:00:52.855374 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.375)       0:00:10.534 ***********
2026-06-08 15:00:52.885641 | controller |
2026-06-08 15:00:52.886243 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 15:00:52.886485 | controller | Monday 08 June 2026  15:00:52 +0000 (0:00:00.030)       0:00:10.565 ***********
2026-06-08 15:00:53.229215 | controller | ok: [instance]
2026-06-08 15:00:53.229346 | controller |
2026-06-08 15:00:53.229470 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 15:00:53.229592 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.343)       0:00:10.908 ***********
2026-06-08 15:00:53.260451 | controller | ok: [instance]
2026-06-08 15:00:53.260575 | controller |
2026-06-08 15:00:53.260703 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 15:00:53.260938 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.031)       0:00:10.940 ***********
2026-06-08 15:00:53.308521 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 15:00:53.313262 | controller |
2026-06-08 15:00:53.315254 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-06-08 15:00:53.315482 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.052)       0:00:10.993 ***********
2026-06-08 15:00:53.333024 | controller | ok: [instance] => {
2026-06-08 15:00:53.333165 | controller |     "changed": false,
2026-06-08 15:00:53.333353 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:53.333508 | controller | }
2026-06-08 15:00:53.333632 | controller |
2026-06-08 15:00:53.333770 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-06-08 15:00:53.333891 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.019)       0:00:11.012 ***********
2026-06-08 15:00:53.365714 | 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 15:00:53.365785 | controller |
2026-06-08 15:00:53.365876 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-06-08 15:00:53.366046 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.032)       0:00:11.045 ***********
2026-06-08 15:00:53.703639 | controller | ok: [instance]
2026-06-08 15:00:53.703790 | controller |
2026-06-08 15:00:53.704044 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-06-08 15:00:53.704246 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.337)       0:00:11.383 ***********
2026-06-08 15:00:53.756481 | controller |
2026-06-08 15:00:53.756561 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 15:00:53.756683 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.053)       0:00:11.436 ***********
2026-06-08 15:00:53.778579 | 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 15:00:53.778718 | controller |
2026-06-08 15:00:53.778870 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 15:00:53.779043 | controller | Monday 08 June 2026  15:00:53 +0000 (0:00:00.022)       0:00:11.458 ***********
2026-06-08 15:00:54.138236 | controller | ok: [instance]
2026-06-08 15:00:54.138366 | controller |
2026-06-08 15:00:54.138530 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 15:00:54.138673 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.358)       0:00:11.817 ***********
2026-06-08 15:00:54.174980 | controller | ok: [instance]
2026-06-08 15:00:54.175096 | controller |
2026-06-08 15:00:54.175246 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 15:00:54.175392 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.037)       0:00:11.854 ***********
2026-06-08 15:00:54.203305 | controller | skipping: [instance]
2026-06-08 15:00:54.203379 | controller |
2026-06-08 15:00:54.203544 | controller | TASK [Query mock state] ********************************************************
2026-06-08 15:00:54.203696 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.028)       0:00:11.882 ***********
2026-06-08 15:00:54.530374 | controller | ok: [instance]
2026-06-08 15:00:54.530443 | controller |
2026-06-08 15:00:54.530592 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-06-08 15:00:54.530767 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.327)       0:00:12.209 ***********
2026-06-08 15:00:54.550587 | controller | ok: [instance] => {
2026-06-08 15:00:54.550752 | controller |     "changed": false,
2026-06-08 15:00:54.550891 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:54.552176 | controller | }
2026-06-08 15:00:54.553418 | controller |
2026-06-08 15:00:54.553541 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-06-08 15:00:54.553683 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.020)       0:00:12.230 ***********
2026-06-08 15:00:54.876365 | controller | ok: [instance]
2026-06-08 15:00:54.876437 | controller |
2026-06-08 15:00:54.876532 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-06-08 15:00:54.876627 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.324)       0:00:12.555 ***********
2026-06-08 15:00:54.925835 | controller |
2026-06-08 15:00:54.925908 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 15:00:54.926026 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.049)       0:00:12.605 ***********
2026-06-08 15:00:54.957139 | 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 15:00:54.957315 | controller |
2026-06-08 15:00:54.957557 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 15:00:54.957804 | controller | Monday 08 June 2026  15:00:54 +0000 (0:00:00.031)       0:00:12.636 ***********
2026-06-08 15:00:55.303380 | controller | ok: [instance]
2026-06-08 15:00:55.303434 | controller |
2026-06-08 15:00:55.303571 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 15:00:55.303695 | controller | Monday 08 June 2026  15:00:55 +0000 (0:00:00.346)       0:00:12.983 ***********
2026-06-08 15:00:55.345918 | controller | ok: [instance]
2026-06-08 15:00:55.346097 | controller |
2026-06-08 15:00:55.346308 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 15:00:55.346505 | controller | Monday 08 June 2026  15:00:55 +0000 (0:00:00.042)       0:00:13.025 ***********
2026-06-08 15:00:55.392078 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 15:00:55.400885 | controller |
2026-06-08 15:00:55.401147 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 15:00:55.401486 | controller | Monday 08 June 2026  15:00:55 +0000 (0:00:00.054)       0:00:13.080 ***********
2026-06-08 15:00:55.432704 | controller | skipping: [instance]
2026-06-08 15:00:55.432782 | controller |
2026-06-08 15:00:55.432896 | controller | TASK [bm_sno : Set GenericUsbBoot BIOS attribute] ******************************
2026-06-08 15:00:55.433065 | controller | Monday 08 June 2026  15:00:55 +0000 (0:00:00.031)       0:00:13.112 ***********
2026-06-08 15:00:55.760955 | controller | ok: [instance]
2026-06-08 15:00:55.760991 | controller |
2026-06-08 15:00:55.761147 | controller | TASK [bm_sno : Create BIOS config job to schedule the change] ******************
2026-06-08 15:00:55.761260 | controller | Monday 08 June 2026  15:00:55 +0000 (0:00:00.328)       0:00:13.441 ***********
2026-06-08 15:00:56.146227 | controller | ok: [instance]
2026-06-08 15:00:56.146352 | controller |
2026-06-08 15:00:56.146625 | controller | TASK [bm_sno : Power off before applying BIOS change] **************************
2026-06-08 15:00:56.146865 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.384)       0:00:13.826 ***********
2026-06-08 15:00:56.169002 | 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 15:00:56.169233 | controller |
2026-06-08 15:00:56.169485 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:56.169710 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.023)       0:00:13.849 ***********
2026-06-08 15:00:56.494008 | controller | ok: [instance]
2026-06-08 15:00:56.494230 | controller |
2026-06-08 15:00:56.494530 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 15:00:56.494763 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.324)       0:00:14.173 ***********
2026-06-08 15:00:56.521362 | controller | skipping: [instance]
2026-06-08 15:00:56.521556 | controller |
2026-06-08 15:00:56.521808 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 15:00:56.522095 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.027)       0:00:14.200 ***********
2026-06-08 15:00:56.545251 | controller | skipping: [instance]
2026-06-08 15:00:56.545384 | controller |
2026-06-08 15:00:56.545638 | controller | TASK [bm_sno : Power on to apply BIOS config job during POST] ******************
2026-06-08 15:00:56.545880 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.023)       0:00:14.224 ***********
2026-06-08 15:00:56.593008 | 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 15:00:56.593275 | controller |
2026-06-08 15:00:56.593544 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:56.593792 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.048)       0:00:14.272 ***********
2026-06-08 15:00:56.959857 | controller | ok: [instance]
2026-06-08 15:00:56.959899 | controller |
2026-06-08 15:00:56.959910 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 15:00:56.959918 | controller | Monday 08 June 2026  15:00:56 +0000 (0:00:00.365)       0:00:14.638 ***********
2026-06-08 15:00:57.319306 | controller | ok: [instance]
2026-06-08 15:00:57.320136 | controller |
2026-06-08 15:00:57.320205 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 15:00:57.320221 | controller | Monday 08 June 2026  15:00:57 +0000 (0:00:00.359)       0:00:14.998 ***********
2026-06-08 15:00:57.760150 | controller | ok: [instance]
2026-06-08 15:00:57.760193 | controller |
2026-06-08 15:00:57.760204 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 15:00:57.760405 | controller | Monday 08 June 2026  15:00:57 +0000 (0:00:00.440)       0:00:15.439 ***********
2026-06-08 15:00:57.814174 | controller | ok: [instance] => {
2026-06-08 15:00:57.814227 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 15:00:57.814242 | controller | }
2026-06-08 15:00:57.814255 | controller |
2026-06-08 15:00:57.814268 | controller | TASK [bm_sno : Power off after BIOS change applied] ****************************
2026-06-08 15:00:57.814281 | controller | Monday 08 June 2026  15:00:57 +0000 (0:00:00.053)       0:00:15.493 ***********
2026-06-08 15:00:57.859024 | 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 15:00:57.859249 | controller |
2026-06-08 15:00:57.859492 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 15:00:57.859728 | controller | Monday 08 June 2026  15:00:57 +0000 (0:00:00.045)       0:00:15.538 ***********
2026-06-08 15:00:58.239701 | controller | ok: [instance]
2026-06-08 15:00:58.240002 | controller |
2026-06-08 15:00:58.240313 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 15:00:58.240572 | controller | Monday 08 June 2026  15:00:58 +0000 (0:00:00.380)       0:00:15.919 ***********
2026-06-08 15:00:58.571372 | controller | ok: [instance]
2026-06-08 15:00:58.571624 | controller |
2026-06-08 15:00:58.571885 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 15:00:58.572173 | controller | Monday 08 June 2026  15:00:58 +0000 (0:00:00.331)       0:00:16.251 ***********
2026-06-08 15:00:58.936695 | controller | ok: [instance]
2026-06-08 15:00:58.936727 | controller |
2026-06-08 15:00:58.936734 | controller | TASK [Query mock state after auto-enable] **************************************
2026-06-08 15:00:58.936741 | controller | Monday 08 June 2026  15:00:58 +0000 (0:00:00.365)       0:00:16.616 ***********
2026-06-08 15:00:59.325984 | controller | ok: [instance]
2026-06-08 15:00:59.326018 | controller |
2026-06-08 15:00:59.326028 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-06-08 15:00:59.326037 | controller | Monday 08 June 2026  15:00:59 +0000 (0:00:00.388)       0:00:17.005 ***********
2026-06-08 15:00:59.353088 | controller | ok: [instance] => {
2026-06-08 15:00:59.353121 | controller |     "changed": false,
2026-06-08 15:00:59.353126 | controller |     "msg": "All assertions passed"
2026-06-08 15:00:59.353130 | controller | }
2026-06-08 15:00:59.353135 | controller |
2026-06-08 15:00:59.353459 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 15:00:59.353502 | controller | Monday 08 June 2026  15:00:59 +0000 (0:00:00.026)       0:00:17.031 ***********
2026-06-08 15:00:59.700102 | controller | ok: [instance]
2026-06-08 15:00:59.700632 | controller |
2026-06-08 15:00:59.700673 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-06-08 15:00:59.700683 | controller | Monday 08 June 2026  15:00:59 +0000 (0:00:00.347)       0:00:17.379 ***********
2026-06-08 15:00:59.757391 | controller |
2026-06-08 15:00:59.757702 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 15:00:59.758012 | controller | Monday 08 June 2026  15:00:59 +0000 (0:00:00.057)       0:00:17.436 ***********
2026-06-08 15:00:59.780885 | 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 15:00:59.781199 | controller |
2026-06-08 15:00:59.781474 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 15:00:59.781735 | controller | Monday 08 June 2026  15:00:59 +0000 (0:00:00.024)       0:00:17.461 ***********
2026-06-08 15:01:00.168519 | controller | ok: [instance]
2026-06-08 15:01:00.168834 | controller |
2026-06-08 15:01:00.169190 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 15:01:00.169561 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.386)       0:00:17.847 ***********
2026-06-08 15:01:00.202992 | controller | ok: [instance]
2026-06-08 15:01:00.203201 | controller |
2026-06-08 15:01:00.203384 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 15:01:00.203607 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.034)       0:00:17.882 ***********
2026-06-08 15:01:00.239160 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 15:01:00.247886 | controller |
2026-06-08 15:01:00.248279 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 15:01:00.248596 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.044)       0:00:17.927 ***********
2026-06-08 15:01:00.280864 | 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 15:01:00.288997 | controller |
2026-06-08 15:01:00.289321 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-06-08 15:01:00.289618 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.041)       0:00:17.968 ***********
2026-06-08 15:01:00.316658 | controller | ok: [instance] => {
2026-06-08 15:01:00.317035 | controller |     "changed": false,
2026-06-08 15:01:00.317449 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:00.317801 | controller | }
2026-06-08 15:01:00.318133 | controller |
2026-06-08 15:01:00.318450 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-06-08 15:01:00.318847 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.027)       0:00:17.996 ***********
2026-06-08 15:01:00.359924 | 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 15:01:00.360195 | controller |
2026-06-08 15:01:00.360377 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 15:01:00.360595 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.043)       0:00:18.039 ***********
2026-06-08 15:01:00.680275 | controller | ok: [instance]
2026-06-08 15:01:00.680657 | controller |
2026-06-08 15:01:00.681015 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-06-08 15:01:00.681359 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.320)       0:00:18.360 ***********
2026-06-08 15:01:00.717328 | controller |
2026-06-08 15:01:00.717817 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 15:01:00.718297 | controller | Monday 08 June 2026  15:01:00 +0000 (0:00:00.036)       0:00:18.396 ***********
2026-06-08 15:01:01.122813 | controller | ok: [instance]
2026-06-08 15:01:01.123152 | controller |
2026-06-08 15:01:01.123439 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 15:01:01.123714 | controller | Monday 08 June 2026  15:01:01 +0000 (0:00:00.405)       0:00:18.802 ***********
2026-06-08 15:01:06.144514 | controller | Pausing for 5 seconds
2026-06-08 15:01:06.144735 | controller | ok: [instance]
2026-06-08 15:01:06.144973 | controller |
2026-06-08 15:01:06.145165 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 15:01:06.145324 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:05.022)       0:00:23.824 ***********
2026-06-08 15:01:06.460466 | controller | ok: [instance]
2026-06-08 15:01:06.460489 | controller |
2026-06-08 15:01:06.460494 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 15:01:06.460499 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.315)       0:00:24.140 ***********
2026-06-08 15:01:06.499091 | controller | ok: [instance] => {
2026-06-08 15:01:06.499121 | controller |     "msg": ""
2026-06-08 15:01:06.499131 | controller | }
2026-06-08 15:01:06.499167 | controller |
2026-06-08 15:01:06.499389 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 15:01:06.499404 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.038)       0:00:24.178 ***********
2026-06-08 15:01:06.548664 | controller | skipping: [instance]
2026-06-08 15:01:06.548691 | controller |
2026-06-08 15:01:06.548698 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 15:01:06.548703 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.049)       0:00:24.228 ***********
2026-06-08 15:01:06.602824 | controller | skipping: [instance]
2026-06-08 15:01:06.602855 | controller |
2026-06-08 15:01:06.602861 | controller | TASK [Query mock state after eject] ********************************************
2026-06-08 15:01:06.602867 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.054)       0:00:24.282 ***********
2026-06-08 15:01:06.951110 | controller | ok: [instance]
2026-06-08 15:01:06.951456 | controller |
2026-06-08 15:01:06.951758 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-06-08 15:01:06.952109 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.348)       0:00:24.631 ***********
2026-06-08 15:01:06.983315 | controller | ok: [instance] => {
2026-06-08 15:01:06.983678 | controller |     "changed": false,
2026-06-08 15:01:06.984053 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:06.984357 | controller | }
2026-06-08 15:01:06.984620 | controller |
2026-06-08 15:01:06.984899 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-06-08 15:01:06.985218 | controller | Monday 08 June 2026  15:01:06 +0000 (0:00:00.032)       0:00:24.663 ***********
2026-06-08 15:01:07.332392 | controller | ok: [instance]
2026-06-08 15:01:07.332574 | controller |
2026-06-08 15:01:07.332730 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-06-08 15:01:07.332861 | controller | Monday 08 June 2026  15:01:07 +0000 (0:00:00.348)       0:00:25.012 ***********
2026-06-08 15:01:07.377392 | controller |
2026-06-08 15:01:07.377549 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 15:01:07.377674 | controller | Monday 08 June 2026  15:01:07 +0000 (0:00:00.045)       0:00:25.057 ***********
2026-06-08 15:01:07.778615 | controller | ok: [instance]
2026-06-08 15:01:07.778979 | controller |
2026-06-08 15:01:07.779337 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 15:01:07.779663 | controller | Monday 08 June 2026  15:01:07 +0000 (0:00:00.400)       0:00:25.458 ***********
2026-06-08 15:01:12.809669 | controller | Pausing for 5 seconds
2026-06-08 15:01:12.810054 | controller | ok: [instance]
2026-06-08 15:01:12.810347 | controller |
2026-06-08 15:01:12.810643 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 15:01:12.810956 | controller | Monday 08 June 2026  15:01:12 +0000 (0:00:05.030)       0:00:30.489 ***********
2026-06-08 15:01:13.057165 | controller | ok: [instance]
2026-06-08 15:01:13.057234 | controller |
2026-06-08 15:01:13.057243 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 15:01:13.057250 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.247)       0:00:30.736 ***********
2026-06-08 15:01:13.101143 | controller | ok: [instance] => {
2026-06-08 15:01:13.101192 | controller |     "msg": ""
2026-06-08 15:01:13.101203 | controller | }
2026-06-08 15:01:13.101579 | controller |
2026-06-08 15:01:13.101622 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 15:01:13.101632 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.044)       0:00:30.780 ***********
2026-06-08 15:01:13.131766 | controller | skipping: [instance]
2026-06-08 15:01:13.131801 | controller |
2026-06-08 15:01:13.131808 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 15:01:13.131814 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.030)       0:00:30.811 ***********
2026-06-08 15:01:13.162522 | controller | skipping: [instance]
2026-06-08 15:01:13.162553 | controller |
2026-06-08 15:01:13.162560 | controller | TASK [Query mock state] ********************************************************
2026-06-08 15:01:13.162565 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.030)       0:00:30.842 ***********
2026-06-08 15:01:13.518124 | controller | ok: [instance]
2026-06-08 15:01:13.518210 | controller |
2026-06-08 15:01:13.518221 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-06-08 15:01:13.518376 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.354)       0:00:31.196 ***********
2026-06-08 15:01:13.579107 | controller | ok: [instance] => {
2026-06-08 15:01:13.579148 | controller |     "changed": false,
2026-06-08 15:01:13.579158 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:13.579168 | controller | }
2026-06-08 15:01:13.579176 | controller |
2026-06-08 15:01:13.579185 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-06-08 15:01:13.579420 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.060)       0:00:31.257 ***********
2026-06-08 15:01:13.664240 | 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 15:01:13.664282 | controller |
2026-06-08 15:01:13.664292 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 15:01:13.664302 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.085)       0:00:31.343 ***********
2026-06-08 15:01:13.679308 | controller | ok: [instance]
2026-06-08 15:01:13.679439 | controller |
2026-06-08 15:01:13.679565 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 15:01:13.679706 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.016)       0:00:31.359 ***********
2026-06-08 15:01:13.996671 | controller | ok: [instance]
2026-06-08 15:01:13.996860 | controller |
2026-06-08 15:01:13.997073 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-06-08 15:01:13.997244 | controller | Monday 08 June 2026  15:01:13 +0000 (0:00:00.316)       0:00:31.676 ***********
2026-06-08 15:01:14.032126 | controller |
2026-06-08 15:01:14.032331 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 15:01:14.032468 | controller | Monday 08 June 2026  15:01:14 +0000 (0:00:00.035)       0:00:31.712 ***********
2026-06-08 15:01:14.390546 | controller | ok: [instance]
2026-06-08 15:01:14.390848 | controller |
2026-06-08 15:01:14.391244 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 15:01:14.391617 | controller | Monday 08 June 2026  15:01:14 +0000 (0:00:00.357)       0:00:32.070 ***********
2026-06-08 15:01:16.050100 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:16.050126 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:16.050131 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:16.050134 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:16.050138 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:16.050142 | controller | ok: [instance]
2026-06-08 15:01:16.050398 | controller |
2026-06-08 15:01:16.050425 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 15:01:16.050431 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:01.659)       0:00:33.729 ***********
2026-06-08 15:01:16.099919 | controller | ok: [instance]
2026-06-08 15:01:16.099950 | controller |
2026-06-08 15:01:16.099955 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 15:01:16.099960 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.050)       0:00:33.779 ***********
2026-06-08 15:01:16.135045 | controller | ok: [instance] => {
2026-06-08 15:01:16.135075 | controller |     "msg": [
2026-06-08 15:01:16.135081 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 15:01:16.135093 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 15:01:16.135099 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 15:01:16.135104 | 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 15:01:16.135109 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:01:16.135114 | controller |     ]
2026-06-08 15:01:16.135119 | controller | }
2026-06-08 15:01:16.135124 | controller |
2026-06-08 15:01:16.135128 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 15:01:16.135136 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.034)       0:00:33.814 ***********
2026-06-08 15:01:16.164012 | controller | skipping: [instance]
2026-06-08 15:01:16.164033 | controller |
2026-06-08 15:01:16.164204 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 15:01:16.164220 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.029)       0:00:33.844 ***********
2026-06-08 15:01:16.237882 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:16.237897 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:16.237902 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:16.237907 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:16.237912 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:16.237917 | controller |
2026-06-08 15:01:16.237922 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 15:01:16.237969 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.073)       0:00:33.917 ***********
2026-06-08 15:01:16.299974 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:16.300121 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:16.300258 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:16.300404 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:16.300542 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:16.300675 | controller | skipping: [instance]
2026-06-08 15:01:16.300801 | controller |
2026-06-08 15:01:16.300964 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 15:01:16.301110 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.062)       0:00:33.980 ***********
2026-06-08 15:01:16.362123 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:16.362297 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:16.362443 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:16.362587 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:16.362723 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:16.362856 | controller | skipping: [instance]
2026-06-08 15:01:16.363003 | controller |
2026-06-08 15:01:16.363143 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 15:01:16.363278 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.062)       0:00:34.042 ***********
2026-06-08 15:01:16.437254 | controller | skipping: [instance]
2026-06-08 15:01:16.437392 | controller |
2026-06-08 15:01:16.437520 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 15:01:16.437646 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.074)       0:00:34.117 ***********
2026-06-08 15:01:16.457470 | controller | ok: [instance] => {
2026-06-08 15:01:16.457610 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:16.457729 | controller | }
2026-06-08 15:01:16.457841 | controller |
2026-06-08 15:01:16.457995 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 15:01:16.458120 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.020)       0:00:34.137 ***********
2026-06-08 15:01:16.791091 | controller | ok: [instance]
2026-06-08 15:01:16.791123 | controller |
2026-06-08 15:01:16.791346 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 15:01:16.791378 | controller | Monday 08 June 2026  15:01:16 +0000 (0:00:00.333)       0:00:34.470 ***********
2026-06-08 15:01:26.824224 | controller | Pausing for 10 seconds
2026-06-08 15:01:26.824262 | controller | ok: [instance]
2026-06-08 15:01:26.824272 | controller |
2026-06-08 15:01:26.824281 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 15:01:26.824290 | controller | Monday 08 June 2026  15:01:26 +0000 (0:00:10.032)       0:00:44.503 ***********
2026-06-08 15:01:27.216152 | controller | ok: [instance]
2026-06-08 15:01:27.216199 | controller |
2026-06-08 15:01:27.216210 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 15:01:27.216385 | controller | Monday 08 June 2026  15:01:27 +0000 (0:00:00.391)       0:00:44.894 ***********
2026-06-08 15:01:27.610426 | controller | ok: [instance]
2026-06-08 15:01:27.610453 | controller |
2026-06-08 15:01:27.610458 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 15:01:27.610463 | controller | Monday 08 June 2026  15:01:27 +0000 (0:00:00.395)       0:00:45.290 ***********
2026-06-08 15:01:27.673164 | controller | ok: [instance] => {
2026-06-08 15:01:27.673206 | controller |     "changed": false,
2026-06-08 15:01:27.673228 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:27.673234 | controller | }
2026-06-08 15:01:27.673269 | controller |
2026-06-08 15:01:27.673660 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 15:01:27.673695 | controller | Monday 08 June 2026  15:01:27 +0000 (0:00:00.062)       0:00:45.352 ***********
2026-06-08 15:01:27.693480 | controller | ok: [instance] => {
2026-06-08 15:01:27.693800 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:27.694151 | controller | }
2026-06-08 15:01:27.694459 | controller |
2026-06-08 15:01:27.694750 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 15:01:27.695086 | controller | Monday 08 June 2026  15:01:27 +0000 (0:00:00.021)       0:00:45.373 ***********
2026-06-08 15:01:28.078772 | controller | ok: [instance]
2026-06-08 15:01:28.078805 | controller |
2026-06-08 15:01:28.078812 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 15:01:28.078819 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.384)       0:00:45.758 ***********
2026-06-08 15:01:28.117050 | controller | ok: [instance] => {
2026-06-08 15:01:28.117089 | controller |     "changed": false,
2026-06-08 15:01:28.117097 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:28.117530 | controller | }
2026-06-08 15:01:28.117548 | controller |
2026-06-08 15:01:28.117556 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-06-08 15:01:28.117564 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.038)       0:00:45.796 ***********
2026-06-08 15:01:28.156069 | controller | ok: [instance] => {
2026-06-08 15:01:28.156094 | controller |     "changed": false,
2026-06-08 15:01:28.156099 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:28.156104 | controller | }
2026-06-08 15:01:28.156107 | controller |
2026-06-08 15:01:28.156111 | controller | TASK [Query mock state after discover] *****************************************
2026-06-08 15:01:28.156115 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.038)       0:00:45.835 ***********
2026-06-08 15:01:28.498761 | controller | ok: [instance]
2026-06-08 15:01:28.498901 | controller |
2026-06-08 15:01:28.499062 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 15:01:28.499216 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.343)       0:00:46.178 ***********
2026-06-08 15:01:28.525389 | controller | ok: [instance] => {
2026-06-08 15:01:28.525549 | controller |     "changed": false,
2026-06-08 15:01:28.525694 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:28.525829 | controller | }
2026-06-08 15:01:28.525979 | controller |
2026-06-08 15:01:28.526139 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 15:01:28.526280 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.026)       0:00:46.205 ***********
2026-06-08 15:01:28.908502 | controller | ok: [instance]
2026-06-08 15:01:28.908615 | controller |
2026-06-08 15:01:28.908729 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-06-08 15:01:28.908859 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.382)       0:00:46.587 ***********
2026-06-08 15:01:28.967648 | controller |
2026-06-08 15:01:28.967768 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 15:01:28.967879 | controller | Monday 08 June 2026  15:01:28 +0000 (0:00:00.059)       0:00:46.647 ***********
2026-06-08 15:01:29.328798 | controller | ok: [instance]
2026-06-08 15:01:29.328826 | controller |
2026-06-08 15:01:29.328831 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 15:01:29.328836 | controller | Monday 08 June 2026  15:01:29 +0000 (0:00:00.361)       0:00:47.008 ***********
2026-06-08 15:01:30.910064 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:30.910105 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:30.910112 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:30.910117 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:30.910123 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:30.910128 | controller | ok: [instance]
2026-06-08 15:01:30.910134 | controller |
2026-06-08 15:01:30.910243 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 15:01:30.910272 | controller | Monday 08 June 2026  15:01:30 +0000 (0:00:01.580)       0:00:48.589 ***********
2026-06-08 15:01:30.945105 | controller | ok: [instance]
2026-06-08 15:01:30.945153 | controller |
2026-06-08 15:01:30.945164 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 15:01:30.945174 | controller | Monday 08 June 2026  15:01:30 +0000 (0:00:00.035)       0:00:48.625 ***********
2026-06-08 15:01:31.000078 | controller | ok: [instance] => {
2026-06-08 15:01:31.000112 | controller |     "msg": [
2026-06-08 15:01:31.000119 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 15:01:31.000125 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 15:01:31.000131 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 15:01:31.000136 | 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 15:01:31.000142 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:01:31.000148 | controller |     ]
2026-06-08 15:01:31.000153 | controller | }
2026-06-08 15:01:31.000158 | controller |
2026-06-08 15:01:31.000164 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 15:01:31.000173 | controller | Monday 08 June 2026  15:01:30 +0000 (0:00:00.053)       0:00:48.678 ***********
2026-06-08 15:01:31.055016 | controller | ok: [instance] => {
2026-06-08 15:01:31.055054 | controller |     "changed": false,
2026-06-08 15:01:31.055061 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:31.055067 | controller | }
2026-06-08 15:01:31.055072 | controller |
2026-06-08 15:01:31.055078 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 15:01:31.055156 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.055)       0:00:48.733 ***********
2026-06-08 15:01:31.122699 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:31.123036 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:31.123318 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:31.123641 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:31.124026 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:31.124300 | controller | skipping: [instance]
2026-06-08 15:01:31.124566 | controller |
2026-06-08 15:01:31.124898 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 15:01:31.125242 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.068)       0:00:48.802 ***********
2026-06-08 15:01:31.215547 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:31.215807 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:31.216095 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:31.216366 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:31.216615 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:31.216909 | controller | skipping: [instance]
2026-06-08 15:01:31.217178 | controller |
2026-06-08 15:01:31.217430 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 15:01:31.217676 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.093)       0:00:48.895 ***********
2026-06-08 15:01:31.321316 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:31.321627 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:31.321901 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 15:01:31.322195 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:31.322464 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:31.322751 | controller | skipping: [instance]
2026-06-08 15:01:31.323100 | controller |
2026-06-08 15:01:31.323381 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 15:01:31.323689 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.105)       0:00:49.000 ***********
2026-06-08 15:01:31.359561 | controller | skipping: [instance]
2026-06-08 15:01:31.359772 | controller |
2026-06-08 15:01:31.360116 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 15:01:31.360465 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.038)       0:00:49.039 ***********
2026-06-08 15:01:31.394526 | controller | ok: [instance] => {
2026-06-08 15:01:31.394824 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:31.395141 | controller | }
2026-06-08 15:01:31.395447 | controller |
2026-06-08 15:01:31.395759 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 15:01:31.396029 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.034)       0:00:49.073 ***********
2026-06-08 15:01:31.781912 | controller | ok: [instance]
2026-06-08 15:01:31.782023 | controller |
2026-06-08 15:01:31.782035 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 15:01:31.782045 | controller | Monday 08 June 2026  15:01:31 +0000 (0:00:00.387)       0:00:49.461 ***********
2026-06-08 15:01:41.825296 | controller | Pausing for 10 seconds
2026-06-08 15:01:41.825406 | controller | ok: [instance]
2026-06-08 15:01:41.825418 | controller |
2026-06-08 15:01:41.825427 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 15:01:41.825436 | controller | Monday 08 June 2026  15:01:41 +0000 (0:00:10.042)       0:00:59.503 ***********
2026-06-08 15:01:42.184391 | controller | ok: [instance]
2026-06-08 15:01:42.184782 | controller |
2026-06-08 15:01:42.184809 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 15:01:42.185064 | controller | Monday 08 June 2026  15:01:42 +0000 (0:00:00.360)       0:00:59.863 ***********
2026-06-08 15:01:42.615857 | controller | ok: [instance]
2026-06-08 15:01:42.615909 | controller |
2026-06-08 15:01:42.615917 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 15:01:42.615958 | controller | Monday 08 June 2026  15:01:42 +0000 (0:00:00.431)       0:01:00.295 ***********
2026-06-08 15:01:42.654464 | controller | ok: [instance] => {
2026-06-08 15:01:42.654502 | controller |     "changed": false,
2026-06-08 15:01:42.654512 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:42.654522 | controller | }
2026-06-08 15:01:42.654531 | controller |
2026-06-08 15:01:42.654539 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 15:01:42.654548 | controller | Monday 08 June 2026  15:01:42 +0000 (0:00:00.037)       0:01:00.333 ***********
2026-06-08 15:01:42.675140 | controller | ok: [instance] => {
2026-06-08 15:01:42.675193 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:42.675200 | controller | }
2026-06-08 15:01:42.675206 | controller |
2026-06-08 15:01:42.675418 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 15:01:42.675449 | controller | Monday 08 June 2026  15:01:42 +0000 (0:00:00.021)       0:01:00.354 ***********
2026-06-08 15:01:43.072056 | controller | ok: [instance]
2026-06-08 15:01:43.072097 | controller |
2026-06-08 15:01:43.072108 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 15:01:43.072335 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.396)       0:01:00.751 ***********
2026-06-08 15:01:43.133141 | controller | ok: [instance] => {
2026-06-08 15:01:43.133177 | controller |     "changed": false,
2026-06-08 15:01:43.133188 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:43.134035 | controller | }
2026-06-08 15:01:43.134061 | controller |
2026-06-08 15:01:43.134071 | controller | TASK [Query mock state] ********************************************************
2026-06-08 15:01:43.134235 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.060)       0:01:00.811 ***********
2026-06-08 15:01:43.512227 | controller | ok: [instance]
2026-06-08 15:01:43.512406 | controller |
2026-06-08 15:01:43.512563 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-06-08 15:01:43.512716 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.379)       0:01:01.191 ***********
2026-06-08 15:01:43.549958 | controller | ok: [instance] => {
2026-06-08 15:01:43.550136 | controller |     "changed": false,
2026-06-08 15:01:43.550286 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:43.550433 | controller | }
2026-06-08 15:01:43.550569 | controller |
2026-06-08 15:01:43.550710 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 15:01:43.550856 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.038)       0:01:01.229 ***********
2026-06-08 15:01:43.571791 | controller | ok: [instance]
2026-06-08 15:01:43.571950 | controller |
2026-06-08 15:01:43.572170 | controller | TASK [Reset mock without Virtual Optical Drive] ********************************
2026-06-08 15:01:43.572314 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.021)       0:01:01.251 ***********
2026-06-08 15:01:43.940860 | controller | ok: [instance]
2026-06-08 15:01:43.940898 | controller |
2026-06-08 15:01:43.940905 | controller | TASK [Include bm_discover_vmedia_target (floppy fallback)] *********************
2026-06-08 15:01:43.940911 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.367)       0:01:01.619 ***********
2026-06-08 15:01:44.002635 | controller |
2026-06-08 15:01:44.002664 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 15:01:44.002669 | controller | Monday 08 June 2026  15:01:43 +0000 (0:00:00.062)       0:01:01.682 ***********
2026-06-08 15:01:44.397508 | controller | ok: [instance]
2026-06-08 15:01:44.397550 | controller |
2026-06-08 15:01:44.397568 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 15:01:44.397577 | controller | Monday 08 June 2026  15:01:44 +0000 (0:00:00.393)       0:01:02.075 ***********
2026-06-08 15:01:45.781154 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:45.781203 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:45.781215 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:45.781226 | controller | ok: [instance] => (item=None)
2026-06-08 15:01:45.781236 | controller | ok: [instance]
2026-06-08 15:01:45.781672 | controller |
2026-06-08 15:01:45.781718 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 15:01:45.781729 | controller | Monday 08 June 2026  15:01:45 +0000 (0:00:01.383)       0:01:03.459 ***********
2026-06-08 15:01:45.849170 | controller | ok: [instance]
2026-06-08 15:01:45.849249 | controller |
2026-06-08 15:01:45.849264 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 15:01:45.849276 | controller | Monday 08 June 2026  15:01:45 +0000 (0:00:00.067)       0:01:03.527 ***********
2026-06-08 15:01:45.898170 | controller | ok: [instance] => {
2026-06-08 15:01:45.898226 | controller |     "msg": [
2026-06-08 15:01:45.898236 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 15:01:45.898243 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 15:01:45.898256 | 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 15:01:45.898552 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:01:45.898888 | controller |     ]
2026-06-08 15:01:45.899182 | controller | }
2026-06-08 15:01:45.899431 | controller |
2026-06-08 15:01:45.899684 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 15:01:45.900108 | controller | Monday 08 June 2026  15:01:45 +0000 (0:00:00.049)       0:01:03.576 ***********
2026-06-08 15:01:45.943739 | controller | skipping: [instance]
2026-06-08 15:01:45.944885 | controller |
2026-06-08 15:01:45.945059 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 15:01:45.945317 | controller | Monday 08 June 2026  15:01:45 +0000 (0:00:00.044)       0:01:03.621 ***********
2026-06-08 15:01:46.023172 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:46.023386 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:46.023618 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:46.023838 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:46.024121 | controller | skipping: [instance]
2026-06-08 15:01:46.024323 | controller |
2026-06-08 15:01:46.024571 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 15:01:46.024787 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.080)       0:01:03.702 ***********
2026-06-08 15:01:46.096494 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:46.096836 | controller | ok: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:46.097181 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:46.097492 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:46.097761 | controller |
2026-06-08 15:01:46.098090 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 15:01:46.098449 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.073)       0:01:03.776 ***********
2026-06-08 15:01:46.154742 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:01:46.155173 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 15:01:46.155509 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:01:46.155802 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:01:46.156186 | controller | skipping: [instance]
2026-06-08 15:01:46.156494 | controller |
2026-06-08 15:01:46.156789 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 15:01:46.157202 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.058)       0:01:03.834 ***********
2026-06-08 15:01:46.188787 | controller | skipping: [instance]
2026-06-08 15:01:46.189205 | controller |
2026-06-08 15:01:46.189554 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 15:01:46.189864 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.034)       0:01:03.868 ***********
2026-06-08 15:01:46.218255 | controller | ok: [instance] => {
2026-06-08 15:01:46.218410 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:46.218565 | controller | }
2026-06-08 15:01:46.218716 | controller |
2026-06-08 15:01:46.218963 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 15:01:46.219081 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.029)       0:01:03.898 ***********
2026-06-08 15:01:46.599090 | controller | ok: [instance]
2026-06-08 15:01:46.599638 | controller |
2026-06-08 15:01:46.599677 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 15:01:46.599687 | controller | Monday 08 June 2026  15:01:46 +0000 (0:00:00.380)       0:01:04.278 ***********
2026-06-08 15:01:56.636092 | controller | Pausing for 10 seconds
2026-06-08 15:01:56.636134 | controller | ok: [instance]
2026-06-08 15:01:56.636145 | controller |
2026-06-08 15:01:56.636154 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 15:01:56.636247 | controller | Monday 08 June 2026  15:01:56 +0000 (0:00:10.036)       0:01:14.315 ***********
2026-06-08 15:01:57.044793 | controller | ok: [instance]
2026-06-08 15:01:57.044835 | controller |
2026-06-08 15:01:57.044846 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 15:01:57.044856 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.408)       0:01:14.723 ***********
2026-06-08 15:01:57.409143 | controller | ok: [instance]
2026-06-08 15:01:57.409191 | controller |
2026-06-08 15:01:57.409201 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 15:01:57.409210 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.364)       0:01:15.088 ***********
2026-06-08 15:01:57.460153 | controller | ok: [instance] => {
2026-06-08 15:01:57.460203 | controller |     "changed": false,
2026-06-08 15:01:57.460218 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:57.460241 | controller | }
2026-06-08 15:01:57.460436 | controller |
2026-06-08 15:01:57.460469 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 15:01:57.460474 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.051)       0:01:15.139 ***********
2026-06-08 15:01:57.492757 | controller | ok: [instance] => {
2026-06-08 15:01:57.492786 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 15:01:57.492791 | controller | }
2026-06-08 15:01:57.492795 | controller |
2026-06-08 15:01:57.492799 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 15:01:57.492804 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.032)       0:01:15.171 ***********
2026-06-08 15:01:57.894752 | controller | ok: [instance]
2026-06-08 15:01:57.894791 | controller |
2026-06-08 15:01:57.894801 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 15:01:57.894810 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.401)       0:01:15.573 ***********
2026-06-08 15:01:57.962327 | controller | ok: [instance] => {
2026-06-08 15:01:57.962370 | controller |     "changed": false,
2026-06-08 15:01:57.962380 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:57.962390 | controller | }
2026-06-08 15:01:57.962398 | controller |
2026-06-08 15:01:57.962406 | controller | TASK [Assert derived path uses Unit(0x0) from Floppy Unit(0x1)] ****************
2026-06-08 15:01:57.962421 | controller | Monday 08 June 2026  15:01:57 +0000 (0:00:00.067)       0:01:15.640 ***********
2026-06-08 15:01:58.027079 | controller | ok: [instance] => {
2026-06-08 15:01:58.027123 | controller |     "changed": false,
2026-06-08 15:01:58.027130 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:58.027136 | controller | }
2026-06-08 15:01:58.027142 | controller |
2026-06-08 15:01:58.027148 | controller | TASK [Query mock state after floppy fallback] **********************************
2026-06-08 15:01:58.027153 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.064)       0:01:15.705 ***********
2026-06-08 15:01:58.467063 | controller | ok: [instance]
2026-06-08 15:01:58.467103 | controller |
2026-06-08 15:01:58.467114 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 15:01:58.467123 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.439)       0:01:16.145 ***********
2026-06-08 15:01:58.515243 | controller | ok: [instance] => {
2026-06-08 15:01:58.515318 | controller |     "changed": false,
2026-06-08 15:01:58.515329 | controller |     "msg": "All assertions passed"
2026-06-08 15:01:58.516343 | controller | }
2026-06-08 15:01:58.516456 | controller |
2026-06-08 15:01:58.516471 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 15:01:58.516484 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.047)       0:01:16.193 ***********
2026-06-08 15:01:58.537913 | controller | ok: [instance]
2026-06-08 15:01:58.538216 | controller |
2026-06-08 15:01:58.538465 | controller | TASK [Reset mock without Virtual Optical or Floppy Drive] **********************
2026-06-08 15:01:58.538718 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.024)       0:01:16.217 ***********
2026-06-08 15:01:58.919116 | controller | ok: [instance]
2026-06-08 15:01:58.919197 | controller |
2026-06-08 15:01:58.919209 | controller | TASK [Include bm_discover_vmedia_target (generic usb fallback)] ****************
2026-06-08 15:01:58.919227 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.380)       0:01:16.598 ***********
2026-06-08 15:01:58.977030 | controller |
2026-06-08 15:01:58.977072 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 15:01:58.977083 | controller | Monday 08 June 2026  15:01:58 +0000 (0:00:00.057)       0:01:16.656 ***********
2026-06-08 15:01:59.407395 | controller | ok: [instance]
2026-06-08 15:01:59.407435 | controller |
2026-06-08 15:01:59.407479 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 15:01:59.407490 | controller | Monday 08 June 2026  15:01:59 +0000 (0:00:00.430)       0:01:17.086 ***********
2026-06-08 15:02:00.552994 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:00.553026 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:00.553032 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:00.553037 | controller | ok: [instance]
2026-06-08 15:02:00.553043 | controller |
2026-06-08 15:02:00.553048 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 15:02:00.553061 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:01.145)       0:01:18.232 ***********
2026-06-08 15:02:00.596168 | controller | ok: [instance]
2026-06-08 15:02:00.596212 | controller |
2026-06-08 15:02:00.596221 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 15:02:00.596229 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.043)       0:01:18.275 ***********
2026-06-08 15:02:00.662107 | controller | ok: [instance] => {
2026-06-08 15:02:00.662146 | controller |     "msg": [
2026-06-08 15:02:00.662155 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 15:02:00.663548 | 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 15:02:00.663595 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:02:00.663605 | controller |     ]
2026-06-08 15:02:00.663615 | controller | }
2026-06-08 15:02:00.663623 | controller |
2026-06-08 15:02:00.663632 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 15:02:00.663640 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.065)       0:01:18.341 ***********
2026-06-08 15:02:00.707793 | controller | skipping: [instance]
2026-06-08 15:02:00.708121 | controller |
2026-06-08 15:02:00.708406 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 15:02:00.708731 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.046)       0:01:18.387 ***********
2026-06-08 15:02:00.797341 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:02:00.797779 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:02:00.798123 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:02:00.798407 | controller | skipping: [instance]
2026-06-08 15:02:00.798775 | controller |
2026-06-08 15:02:00.799103 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 15:02:00.799378 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.088)       0:01:18.476 ***********
2026-06-08 15:02:00.885691 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:02:00.886149 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:02:00.886433 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 15:02:00.886696 | controller | skipping: [instance]
2026-06-08 15:02:00.886999 | controller |
2026-06-08 15:02:00.887284 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 15:02:00.888589 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.088)       0:01:18.565 ***********
2026-06-08 15:02:00.977962 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 15:02:00.978003 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 15:02:00.978016 | controller | ok: [instance] => (item=Generic USB Boot)
2026-06-08 15:02:00.978026 | controller |
2026-06-08 15:02:00.978035 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 15:02:00.978044 | controller | Monday 08 June 2026  15:02:00 +0000 (0:00:00.091)       0:01:18.656 ***********
2026-06-08 15:02:01.028900 | controller | skipping: [instance]
2026-06-08 15:02:01.028987 | controller |
2026-06-08 15:02:01.029001 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 15:02:01.029010 | controller | Monday 08 June 2026  15:02:01 +0000 (0:00:00.051)       0:01:18.707 ***********
2026-06-08 15:02:01.065179 | controller | ok: [instance] => {
2026-06-08 15:02:01.065227 | controller |     "msg": "VirtualMedia UEFI path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:02:01.065238 | controller | }
2026-06-08 15:02:01.065801 | controller |
2026-06-08 15:02:01.065839 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 15:02:01.065851 | controller | Monday 08 June 2026  15:02:01 +0000 (0:00:00.036)       0:01:18.744 ***********
2026-06-08 15:02:01.434458 | controller | ok: [instance]
2026-06-08 15:02:01.434498 | controller |
2026-06-08 15:02:01.434508 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 15:02:01.434518 | controller | Monday 08 June 2026  15:02:01 +0000 (0:00:00.368)       0:01:19.113 ***********
2026-06-08 15:02:11.470157 | controller | Pausing for 10 seconds
2026-06-08 15:02:11.470199 | controller | ok: [instance]
2026-06-08 15:02:11.470210 | controller |
2026-06-08 15:02:11.470219 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 15:02:11.470234 | controller | Monday 08 June 2026  15:02:11 +0000 (0:00:10.035)       0:01:29.148 ***********
2026-06-08 15:02:11.896109 | controller | ok: [instance]
2026-06-08 15:02:11.896604 | controller |
2026-06-08 15:02:11.896645 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 15:02:11.896655 | controller | Monday 08 June 2026  15:02:11 +0000 (0:00:00.427)       0:01:29.575 ***********
2026-06-08 15:02:12.550770 | controller | ok: [instance]
2026-06-08 15:02:12.550810 | controller |
2026-06-08 15:02:12.550819 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 15:02:12.550827 | controller | Monday 08 June 2026  15:02:12 +0000 (0:00:00.654)       0:01:30.229 ***********
2026-06-08 15:02:12.593149 | controller | ok: [instance] => {
2026-06-08 15:02:12.593182 | controller |     "changed": false,
2026-06-08 15:02:12.593189 | controller |     "msg": "All assertions passed"
2026-06-08 15:02:12.593196 | controller | }
2026-06-08 15:02:12.593202 | controller |
2026-06-08 15:02:12.593207 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 15:02:12.593213 | controller | Monday 08 June 2026  15:02:12 +0000 (0:00:00.042)       0:01:30.271 ***********
2026-06-08 15:02:12.618105 | controller | ok: [instance] => {
2026-06-08 15:02:12.618144 | controller |     "msg": "Resolved boot path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:02:12.618155 | controller | }
2026-06-08 15:02:12.618816 | controller |
2026-06-08 15:02:12.618865 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 15:02:12.618879 | controller | Monday 08 June 2026  15:02:12 +0000 (0:00:00.025)       0:01:30.297 ***********
2026-06-08 15:02:13.011072 | controller | ok: [instance]
2026-06-08 15:02:13.011126 | controller |
2026-06-08 15:02:13.011162 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 15:02:13.011233 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.394)       0:01:30.691 ***********
2026-06-08 15:02:13.052920 | controller | ok: [instance] => {
2026-06-08 15:02:13.053165 | controller |     "changed": false,
2026-06-08 15:02:13.053222 | controller |     "msg": "All assertions passed"
2026-06-08 15:02:13.053446 | controller | }
2026-06-08 15:02:13.053604 | controller |
2026-06-08 15:02:13.053819 | controller | TASK [Assert Generic USB Boot path was used] ***********************************
2026-06-08 15:02:13.054092 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.041)       0:01:30.732 ***********
2026-06-08 15:02:13.119208 | controller | ok: [instance] => {
2026-06-08 15:02:13.119257 | controller |     "changed": false,
2026-06-08 15:02:13.119268 | controller |     "msg": "All assertions passed"
2026-06-08 15:02:13.120046 | controller | }
2026-06-08 15:02:13.120089 | controller |
2026-06-08 15:02:13.120100 | controller | TASK [Query mock state after generic usb fallback] *****************************
2026-06-08 15:02:13.120110 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.065)       0:01:30.798 ***********
2026-06-08 15:02:13.487920 | controller | ok: [instance]
2026-06-08 15:02:13.487982 | controller |
2026-06-08 15:02:13.487992 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 15:02:13.488001 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.368)       0:01:31.166 ***********
2026-06-08 15:02:13.514151 | controller | ok: [instance] => {
2026-06-08 15:02:13.514195 | controller |     "changed": false,
2026-06-08 15:02:13.514205 | controller |     "msg": "All assertions passed"
2026-06-08 15:02:13.514214 | controller | }
2026-06-08 15:02:13.514223 | controller |
2026-06-08 15:02:13.514431 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 15:02:13.514471 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.025)       0:01:31.192 ***********
2026-06-08 15:02:13.899130 | controller | ok: [instance]
2026-06-08 15:02:13.899179 | controller |
2026-06-08 15:02:13.899201 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-06-08 15:02:13.899210 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.385)       0:01:31.577 ***********
2026-06-08 15:02:13.953033 | controller |
2026-06-08 15:02:13.953257 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 15:02:13.953284 | controller | Monday 08 June 2026  15:02:13 +0000 (0:00:00.055)       0:01:31.633 ***********
2026-06-08 15:02:14.402260 | controller | ok: [instance]
2026-06-08 15:02:14.402296 | controller |
2026-06-08 15:02:14.402305 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 15:02:14.402313 | controller | Monday 08 June 2026  15:02:14 +0000 (0:00:00.447)       0:01:32.080 ***********
2026-06-08 15:02:16.706161 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:16.706210 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:16.706220 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:16.706228 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:16.706235 | controller | ok: [instance] => (item=None)
2026-06-08 15:02:16.706552 | controller | ok: [instance]
2026-06-08 15:02:16.706583 | controller |
2026-06-08 15:02:16.706589 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 15:02:16.706593 | controller | Monday 08 June 2026  15:02:16 +0000 (0:00:02.304)       0:01:34.385 ***********
2026-06-08 15:02:16.778145 | controller | ok: [instance]
2026-06-08 15:02:16.778190 | controller |
2026-06-08 15:02:16.778479 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 15:02:16.778520 | controller | Monday 08 June 2026  15:02:16 +0000 (0:00:00.071)       0:01:34.457 ***********
2026-06-08 15:02:16.843171 | controller | ok: [instance] => {
2026-06-08 15:02:16.845056 | controller |     "msg": [
2026-06-08 15:02:16.845095 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 15:02:16.845106 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 15:02:16.845114 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 15:02:16.845122 | 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 15:02:16.845131 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 15:02:16.845139 | controller |     ]
2026-06-08 15:02:16.845147 | controller | }
2026-06-08 15:02:16.845160 | controller |
2026-06-08 15:02:16.845346 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 15:02:16.845670 | controller | Monday 08 June 2026  15:02:16 +0000 (0:00:00.065)       0:01:34.522 ***********
2026-06-08 15:02:16.898596 | controller | fatal: [instance]: FAILED! => {
2026-06-08 15:02:16.898700 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-06-08 15:02:16.898811 | controller |     "changed": false,
2026-06-08 15:02:16.898918 | controller |     "evaluated_to": false,
2026-06-08 15:02:16.899066 | 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 15:02:16.899161 | controller | }
2026-06-08 15:02:16.903108 | controller |
2026-06-08 15:02:16.903216 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-06-08 15:02:16.903335 | controller | Monday 08 June 2026  15:02:16 +0000 (0:00:00.061)       0:01:34.583 ***********
2026-06-08 15:02:16.983700 | controller | ok: [instance] => {
2026-06-08 15:02:16.983945 | controller |     "changed": false,
2026-06-08 15:02:16.984232 | controller |     "msg": "All assertions passed"
2026-06-08 15:02:16.984504 | controller | }
2026-06-08 15:02:16.984772 | controller |
2026-06-08 15:02:16.985031 | controller | PLAY RECAP *********************************************************************
2026-06-08 15:02:16.985285 | controller | instance                   : ok=168  changed=0    unreachable=0    failed=0    skipped=28   rescued=5    ignored=0
2026-06-08 15:02:16.985512 | controller |
2026-06-08 15:02:16.985746 | controller | Monday 08 June 2026  15:02:16 +0000 (0:00:00.077)       0:01:34.661 ***********
2026-06-08 15:02:16.985991 | controller | ===============================================================================
2026-06-08 15:02:16.986227 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 15:02:16.986482 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 15:02:16.986717 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 15:02:16.986949 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.03s
2026-06-08 15:02:16.987224 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.03s
2026-06-08 15:02:16.987453 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.02s
2026-06-08 15:02:16.987681 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 2.30s
2026-06-08 15:02:16.987912 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.66s
2026-06-08 15:02:16.988171 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.58s
2026-06-08 15:02:16.988449 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.38s
2026-06-08 15:02:16.988733 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.15s
2026-06-08 15:02:16.989006 | controller | bm_sno : Verify boot override was applied ------------------------------- 0.65s
2026-06-08 15:02:16.989253 | controller | Reset mock to power Off ------------------------------------------------- 0.55s
2026-06-08 15:02:16.989481 | controller | bm_sno : Query current power state -------------------------------------- 0.47s
2026-06-08 15:02:16.989713 | controller | bm_sno : Fetch UEFI boot option IDs ------------------------------------- 0.45s
2026-06-08 15:02:16.989989 | controller | bm_sno : Wait for host POST to complete --------------------------------- 0.44s
2026-06-08 15:02:16.990239 | controller | Query mock state after floppy fallback ---------------------------------- 0.44s
2026-06-08 15:02:16.990475 | controller | bm_sno : Verify boot override was applied ------------------------------- 0.43s
2026-06-08 15:02:16.990710 | controller | bm_sno : Fetch UEFI boot option IDs ------------------------------------- 0.43s
2026-06-08 15:02:16.990950 | controller | bm_sno : Set one-time boot from Virtual Optical Drive ------------------- 0.43s
2026-06-08 15:02:17.079793 | controller | INFO     Running bm_redfish > cleanup
2026-06-08 15:02:17.541421 | controller |
2026-06-08 15:02:17.541737 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-06-08 15:02:17.541995 | controller |
2026-06-08 15:02:17.542312 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-06-08 15:02:17.542585 | controller | Monday 08 June 2026  15:02:17 +0000 (0:00:00.023)       0:00:00.023 ***********
2026-06-08 15:02:17.983774 | controller | ok: [instance]
2026-06-08 15:02:17.983854 | controller |
2026-06-08 15:02:17.983870 | controller | TASK [Show mock server log] ****************************************************
2026-06-08 15:02:17.983896 | controller | Monday 08 June 2026  15:02:17 +0000 (0:00:00.440)       0:00:00.463 ***********
2026-06-08 15:02:18.278066 | controller | ok: [instance]
2026-06-08 15:02:18.278126 | controller |
2026-06-08 15:02:18.278133 | controller | TASK [Print mock server log] ***************************************************
2026-06-08 15:02:18.278188 | controller | Monday 08 June 2026  15:02:18 +0000 (0:00:00.296)       0:00:00.759 ***********
2026-06-08 15:02:18.336980 | controller | ok: [instance] => {
2026-06-08 15:02:18.337031 | controller |     "_mock_log.stdout_lines": [
2026-06-08 15:02:18.337036 | controller |         "Mock iDRAC listening on https://0.0.0.0:8443",
2026-06-08 15:02:18.337040 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337053 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337057 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337061 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337064 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337067 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.337071 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 15:02:18.341952 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341969 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341974 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341977 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341981 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341984 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341988 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341991 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.341995 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 15:02:18.341998 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342001 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342005 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342008 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342011 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 15:02:18.342015 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342018 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342022 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342025 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342028 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342032 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342035 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342038 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342042 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342045 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342049 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342072 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1/Bios/Settings HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342078 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/Jobs HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342082 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342086 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342090 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 15:02:18.342094 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342098 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342105 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 15:02:18.342109 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342113 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342117 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342122 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342126 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342131 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 15:02:18.342136 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342141 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342146 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 15:02:18.342151 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342155 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342160 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342165 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342169 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342174 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342396 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342587 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342771 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 15:02:18.342965 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343164 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343334 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343485 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343645 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343815 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 15:02:18.343982 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344120 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344268 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344436 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344591 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344729 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 15:02:18.344904 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345088 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345237 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345372 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345506 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345675 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345816 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.345955 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346161 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346293 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346434 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346597 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346749 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.346894 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347096 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347268 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347445 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347614 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347782 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.347958 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.348137 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 15:02:18.348306 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.348489 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.348686 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 15:02:18.348865 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 15:02:18.349278 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 15:02:18.349467 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 15:02:18.349620 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.349775 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.350984 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.351204 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 15:02:18.351339 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -"
2026-06-08 15:02:18.351493 | controller |     ]
2026-06-08 15:02:18.351600 | controller | }
2026-06-08 15:02:18.357991 | controller |
2026-06-08 15:02:18.358155 | controller | PLAY RECAP *********************************************************************
2026-06-08 15:02:18.358298 | controller | instance                   : ok=3    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 15:02:18.358422 | controller |
2026-06-08 15:02:18.358552 | controller | Monday 08 June 2026  15:02:18 +0000 (0:00:00.081)       0:00:00.841 ***********
2026-06-08 15:02:18.358690 | controller | ===============================================================================
2026-06-08 15:02:18.358805 | controller | Stop mock iDRAC server -------------------------------------------------- 0.44s
2026-06-08 15:02:18.358947 | controller | Show mock server log ---------------------------------------------------- 0.30s
2026-06-08 15:02:18.359094 | controller | Print mock server log --------------------------------------------------- 0.08s
2026-06-08 15:02:18.431165 | controller | INFO     Writing /tmp/report.html report.
2026-06-08 15:02:18.581527 | controller | ok: Runtime: 0:01:41.361484
2026-06-08 15:02:18.603317 | 
2026-06-08 15:02:18.603472 | PLAY RECAP
2026-06-08 15:02:18.603556 | controller | ok: 4 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 15:02:18.603601 | 
2026-06-08 15:02:18.776309 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 15:02:18.779112 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 15:02:19.416402 | 
2026-06-08 15:02:19.416562 | PLAY [Ensure ci-framework-data base directories exist on all nodes]
2026-06-08 15:02:19.427398 | 
2026-06-08 15:02:19.427472 | TASK [Create ci-framework-data/logs directory if missing]
2026-06-08 15:02:20.037148 | controller | ok
2026-06-08 15:02:20.081821 | 
2026-06-08 15:02:20.081993 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-06-08 15:02:20.088885 | 
2026-06-08 15:02:20.089000 | TASK [Filter out host if needed]
2026-06-08 15:02:20.099082 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-06-08 15:02:20.103388 | 
2026-06-08 15:02:20.103461 | TASK [Ensure file is present]
2026-06-08 15:02:20.694581 | controller | ok
2026-06-08 15:02:20.705956 | 
2026-06-08 15:02:20.706140 | TASK [Manage molecule report file]
2026-06-08 15:02:21.754330 | controller | ok: Runtime: 0:00:00.228715
2026-06-08 15:02:21.763001 | 
2026-06-08 15:02:21.763132 | TASK [Check if we get ci-framework-data basedir]
2026-06-08 15:02:22.144326 | controller | ok
2026-06-08 15:02:22.152570 | 
2026-06-08 15:02:22.152699 | TASK [Create ci-framework-data log directory for zuul]
2026-06-08 15:02:22.444463 | controller | changed
2026-06-08 15:02:22.456441 | 
2026-06-08 15:02:22.456689 | TASK [Copy ci-framework interesting files]
2026-06-08 15:02:22.811717 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-06-08 15:02:23.008800 | controller | ok: Runtime: 0:00:00.064106
2026-06-08 15:02:23.016282 | 
2026-06-08 15:02:23.016458 | TASK [Get SELinux listing]
2026-06-08 15:02:23.566238 | controller | ok: Runtime: 0:00:00.012050
2026-06-08 15:02:23.575613 | 
2026-06-08 15:02:23.575738 | TASK [Generate log index]
2026-06-08 15:02:24.751951 | controller | changed
2026-06-08 15:02:24.761079 | 
2026-06-08 15:02:24.761210 | TASK [Get some env related data]
2026-06-08 15:02:25.454799 | controller | /home/zuul/.local/bin/ansible
2026-06-08 15:02:26.308440 | controller | ok: Runtime: 0:00:01.074061
2026-06-08 15:02:26.353791 | 
2026-06-08 15:02:26.353942 | TASK [Generate list of logs to collect in home directory]
2026-06-08 15:02:26.716948 | controller | ok: All paths examined
2026-06-08 15:02:26.726295 | 
2026-06-08 15:02:26.726481 | LOOP [Copy logs from home directory]
2026-06-08 15:02:27.251929 | controller | changed:
2026-06-08 15:02:27.252126 | controller | {
2026-06-08 15:02:27.252151 | controller |   "atime": 1780930816.0936303,
2026-06-08 15:02:27.252170 | controller |   "ctime": 1780930834.0491326,
2026-06-08 15:02:27.252186 | controller |   "dev": 64513,
2026-06-08 15:02:27.252202 | controller |   "gid": 1000,
2026-06-08 15:02:27.252217 | controller |   "gr_name": "zuul",
2026-06-08 15:02:27.252233 | controller |   "inode": 299144,
2026-06-08 15:02:27.252248 | controller |   "isblk": false,
2026-06-08 15:02:27.252264 | controller |   "ischr": false,
2026-06-08 15:02:27.252279 | controller |   "isdir": false,
2026-06-08 15:02:27.252293 | controller |   "isfifo": false,
2026-06-08 15:02:27.252308 | controller |   "isgid": false,
2026-06-08 15:02:27.252323 | controller |   "islnk": false,
2026-06-08 15:02:27.252338 | controller |   "isreg": true,
2026-06-08 15:02:27.252357 | controller |   "issock": false,
2026-06-08 15:02:27.252459 | controller |   "isuid": false,
2026-06-08 15:02:27.252479 | controller |   "mode": "0644",
2026-06-08 15:02:27.252494 | controller |   "mtime": 1780930834.0491326,
2026-06-08 15:02:27.252509 | controller |   "nlink": 1,
2026-06-08 15:02:27.252524 | controller |   "path": "/home/zuul/ansible.log",
2026-06-08 15:02:27.252539 | controller |   "pw_name": "zuul",
2026-06-08 15:02:27.252553 | controller |   "rgrp": true,
2026-06-08 15:02:27.252568 | controller |   "roth": true,
2026-06-08 15:02:27.252585 | controller |   "rusr": true,
2026-06-08 15:02:27.252600 | controller |   "size": 6749,
2026-06-08 15:02:27.252615 | controller |   "uid": 1000,
2026-06-08 15:02:27.252629 | controller |   "wgrp": false,
2026-06-08 15:02:27.252644 | controller |   "woth": false,
2026-06-08 15:02:27.252658 | controller |   "wusr": true,
2026-06-08 15:02:27.252672 | controller |   "xgrp": false,
2026-06-08 15:02:27.252687 | controller |   "xoth": false,
2026-06-08 15:02:27.252702 | controller |   "xusr": false
2026-06-08 15:02:27.252717 | controller | }
2026-06-08 15:02:27.268176 | 
2026-06-08 15:02:27.268442 | TASK [Copy crio stats log file]
2026-06-08 15:02:27.297014 | controller | skipping: Conditional result was False
2026-06-08 15:02:27.304423 | 
2026-06-08 15:02:27.304552 | TASK [Get SELinux related data]
2026-06-08 15:02:27.655435 | controller | <no matches>
2026-06-08 15:02:27.843538 | controller | ERROR
2026-06-08 15:02:27.843881 | controller | {
2026-06-08 15:02:27.843939 | controller |   "delta": "0:00:00.044272",
2026-06-08 15:02:27.843994 | controller |   "end": "2026-06-08 15:02:27.656557",
2026-06-08 15:02:27.844035 | controller |   "msg": "non-zero return code",
2026-06-08 15:02:27.844069 | controller |   "rc": 1,
2026-06-08 15:02:27.844104 | controller |   "start": "2026-06-08 15:02:27.612285"
2026-06-08 15:02:27.844138 | controller | }
2026-06-08 15:02:27.844182 | controller | ERROR: Ignoring Errors
2026-06-08 15:02:27.852525 | 
2026-06-08 15:02:27.852657 | TASK [Create system configuration directory]
2026-06-08 15:02:28.116662 | controller | changed
2026-06-08 15:02:28.125214 | 
2026-06-08 15:02:28.125344 | TASK [Get some of the system configurations]
2026-06-08 15:02:28.668632 | controller | ok: Runtime: 0:00:00.029634
2026-06-08 15:02:28.672428 | 
2026-06-08 15:02:28.672496 | TASK [Copy generated documentation if available]
2026-06-08 15:02:28.698309 | controller | skipping: Conditional result was False
2026-06-08 15:02:28.703471 | 
2026-06-08 15:02:28.703553 | TASK [Copy generated AsciiDoc documentation if available]
2026-06-08 15:02:28.739632 | controller | skipping: Conditional result was False
2026-06-08 15:02:28.749080 | 
2026-06-08 15:02:28.749261 | TASK [Compress logs bigger than 2MB]
2026-06-08 15:02:29.296265 | controller | ok: Runtime: 0:00:00.007469
2026-06-08 15:02:29.301813 | 
2026-06-08 15:02:29.301908 | TASK [Copy files from workspace on node]
2026-06-08 15:02:29.334486 | controller | ok
2026-06-08 15:02:29.361803 | 
2026-06-08 15:02:29.361970 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 15:02:29.396845 | controller | skipping: Conditional result was False
2026-06-08 15:02:29.406865 | 
2026-06-08 15:02:29.407024 | TASK [fetch-output : Set log path for single node]
2026-06-08 15:02:29.453259 | controller | ok
2026-06-08 15:02:29.461923 | 
2026-06-08 15:02:29.462066 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 15:02:29.783330 | controller -> localhost | changed: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/logs"
2026-06-08 15:02:29.783975 | controller -> localhost | changed: All items complete
2026-06-08 15:02:29.784056 | 
2026-06-08 15:02:30.031070 | controller -> localhost | changed: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/artifacts"
2026-06-08 15:02:30.300573 | controller -> localhost | changed: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/docs"
2026-06-08 15:02:30.317099 | 
2026-06-08 15:02:30.317401 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 15:02:31.434188 | controller | changed:
2026-06-08 15:02:31.434595 | controller | .d..t...... ./
2026-06-08 15:02:31.434678 | controller | >f+++++++++ README.html
2026-06-08 15:02:31.434758 | controller | >f+++++++++ ansible-execution.log
2026-06-08 15:02:31.434809 | controller | >f+++++++++ ansible.log
2026-06-08 15:02:31.434861 | controller | >f+++++++++ dmesg.log
2026-06-08 15:02:31.434908 | controller | >f+++++++++ installed-pkgs.log
2026-06-08 15:02:31.434954 | controller | >f+++++++++ python.log
2026-06-08 15:02:31.434999 | controller | >f+++++++++ registries.conf
2026-06-08 15:02:31.435043 | controller | >f+++++++++ report.html
2026-06-08 15:02:31.435087 | controller | >f+++++++++ selinux-denials.log
2026-06-08 15:02:31.435133 | controller | >f+++++++++ selinux-listing.log
2026-06-08 15:02:31.435177 | controller | cd+++++++++ ci-framework-data/
2026-06-08 15:02:31.435222 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-06-08 15:02:31.435266 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-06-08 15:02:31.435311 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-06-08 15:02:31.435387 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-06-08 15:02:31.435447 | controller | cd+++++++++ ci-framework-data/logs/
2026-06-08 15:02:31.435495 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-06-08 15:02:31.435541 | controller | cd+++++++++ registries.conf.d/
2026-06-08 15:02:31.435586 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-06-08 15:02:31.435721 | controller | cd+++++++++ system-config/
2026-06-08 15:02:31.435771 | controller | cd+++++++++ system-config/libvirt/
2026-06-08 15:02:31.435807 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-06-08 15:02:31.435841 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-06-08 15:02:31.946045 | controller | changed: .d..t...... ./
2026-06-08 15:02:32.538664 | controller | changed: .d..t...... ./
2026-06-08 15:02:32.578517 | 
2026-06-08 15:02:32.578974 | TASK [Return artifact to Zuul]
2026-06-08 15:02:32.635534 | controller | ok
2026-06-08 15:02:32.639651 | 
2026-06-08 15:02:32.639757 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-06-08 15:02:32.639953 | 
2026-06-08 15:02:32.640007 | PLAY RECAP
2026-06-08 15:02:32.640083 | controller | ok: 19 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-06-08 15:02:32.640124 | 
2026-06-08 15:02:32.875507 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 15:02:32.877946 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 15:02:33.601787 | 
2026-06-08 15:02:33.601975 | PLAY [all]
2026-06-08 15:02:33.615987 | 
2026-06-08 15:02:33.616090 | TASK [include_role : fetch-output]
2026-06-08 15:02:33.667463 | controller | ok
2026-06-08 15:02:33.690667 | 
2026-06-08 15:02:33.690840 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 15:02:33.798500 | controller | skipping: Conditional result was False
2026-06-08 15:02:33.808671 | 
2026-06-08 15:02:33.808821 | TASK [fetch-output : Set log path for single node]
2026-06-08 15:02:33.866569 | controller | ok
2026-06-08 15:02:33.896273 | 
2026-06-08 15:02:33.896516 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 15:02:34.365572 | controller -> localhost | ok: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/logs"
2026-06-08 15:02:34.688664 | controller -> localhost | ok: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/artifacts"
2026-06-08 15:02:35.015666 | controller -> localhost | ok: "/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/docs"
2026-06-08 15:02:35.030962 | 
2026-06-08 15:02:35.031171 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 15:02:35.852147 | controller | ok
2026-06-08 15:02:35.852603 | controller | ok: All items complete
2026-06-08 15:02:35.852681 | 
2026-06-08 15:02:36.467072 | controller | ok
2026-06-08 15:02:37.007622 | controller | ok
2026-06-08 15:02:37.033092 | 
2026-06-08 15:02:37.033333 | TASK [include_role : fetch-output-openshift]
2026-06-08 15:02:37.061327 | controller | skipping: Conditional result was False
2026-06-08 15:02:37.071676 | 
2026-06-08 15:02:37.071824 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-06-08 15:02:37.594451 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.014901
2026-06-08 15:02:37.896452 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.014044
2026-06-08 15:02:37.922423 | 
2026-06-08 15:02:37.922625 | PLAY [all]
2026-06-08 15:02:37.932536 | 
2026-06-08 15:02:37.932677 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-06-08 15:02:38.496937 | controller | changed
2026-06-08 15:02:38.509936 | 
2026-06-08 15:02:38.510116 | PLAY RECAP
2026-06-08 15:02:38.510227 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-06-08 15:02:38.510285 | 
2026-06-08 15:02:38.660766 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 15:02:38.663261 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-06-08 15:02:39.334616 | 
2026-06-08 15:02:39.334760 | PLAY [localhost]
2026-06-08 15:02:39.345519 | 
2026-06-08 15:02:39.345594 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-06-08 15:02:39.819681 | localhost | changed
2026-06-08 15:02:39.829909 | 
2026-06-08 15:02:39.830056 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-06-08 15:02:39.868400 | localhost | ok
2026-06-08 15:02:39.874305 | 
2026-06-08 15:02:39.874389 | TASK [add-fileserver : Create SSH private key tempfile]
2026-06-08 15:02:40.339831 | localhost | changed
2026-06-08 15:02:40.350786 | 
2026-06-08 15:02:40.350928 | TASK [add-fileserver : Create SSH private key from secret]
2026-06-08 15:02:41.215557 | localhost | changed
2026-06-08 15:02:41.224585 | 
2026-06-08 15:02:41.224724 | TASK [add-fileserver : Add fileserver ssh key]
2026-06-08 15:02:41.733063 | localhost | Identity added: /var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/tmp/ansible.cqx1y7gn (/var/lib/zuul/builds/ded8c15cec7848879ec1fd32ca9c20e5/work/tmp/ansible.cqx1y7gn)
2026-06-08 15:02:41.733288 | localhost | ok: Runtime: 0:00:00.022077
2026-06-08 15:02:41.736846 | 
2026-06-08 15:02:41.736917 | TASK [add-fileserver : Remove SSH private key from disk]
2026-06-08 15:02:42.070439 | localhost | ok: Runtime: 0:00:00.006696
2026-06-08 15:02:42.074455 | 
2026-06-08 15:02:42.074522 | TASK [add-fileserver : Add fileserver to inventory]
2026-06-08 15:02:42.143423 | localhost | changed
2026-06-08 15:02:42.148497 | 
2026-06-08 15:02:42.148572 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-06-08 15:02:42.618453 | localhost | changed
2026-06-08 15:02:42.629444 | 
2026-06-08 15:02:42.629556 | PLAY [localhost]
2026-06-08 15:02:42.638000 | 
2026-06-08 15:02:42.638123 | TASK [Generate bulk log download script]
2026-06-08 15:02:42.671808 | localhost | ok
2026-06-08 15:02:42.694327 | 
2026-06-08 15:02:42.694486 | TASK [local-log-download : Check API endpoint is defined]
2026-06-08 15:02:42.745200 | localhost | ok: All assertions passed
2026-06-08 15:02:42.750083 | 
2026-06-08 15:02:42.750170 | TASK [local-log-download : Create download script]
2026-06-08 15:02:43.301126 | localhost -> localhost | changed
2026-06-08 15:02:43.356836 | 
2026-06-08 15:02:43.357001 | TASK [Register quick-download link]
2026-06-08 15:02:43.387229 | localhost | ok
2026-06-08 15:02:43.389695 | 
2026-06-08 15:02:43.389748 | PLAY [a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com]
2026-06-08 15:02:43.395316 | 
2026-06-08 15:02:43.395395 | TASK [Set zuul-log-path fact]
2026-06-08 15:02:43.421147 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 15:02:43.427679 | 
2026-06-08 15:02:43.427740 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 15:02:43.464451 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 15:02:43.467168 | 
2026-06-08 15:02:43.467239 | TASK [upload-logs : Create log directories]
2026-06-08 15:02:44.357769 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | changed
2026-06-08 15:02:44.361485 | 
2026-06-08 15:02:44.361617 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-06-08 15:02:44.685178 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com -> localhost | ok: Runtime: 0:00:00.011282
2026-06-08 15:02:44.691976 | 
2026-06-08 15:02:44.692101 | TASK [upload-logs : Upload logs to log server]
2026-06-08 15:02:46.857094 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | Output suppressed because no_log was given
2026-06-08 15:02:46.859846 | 
2026-06-08 15:02:46.859960 | LOOP [upload-logs : Compress console log and json output]