2026-06-08 12:53:11.395818 | Job console starting
2026-06-08 12:53:11.502544 | Updating git repos
2026-06-08 12:53:11.573027 | Cloning repos into workspace
2026-06-08 12:53:13.909551 | Restoring repo states
2026-06-08 12:53:13.929949 | Merging changes
2026-06-08 12:53:15.079290 | Checking out repos
2026-06-08 12:53:15.715387 | Preparing playbooks
2026-06-08 12:53:21.423932 | Running Ansible setup
2026-06-08 12:53:24.968606 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 12:53:25.604138 | 
2026-06-08 12:53:25.604283 | PLAY [localhost]
2026-06-08 12:53:25.612166 | 
2026-06-08 12:53:25.612251 | TASK [Gathering Facts]
2026-06-08 12:53:26.512247 | localhost | ok
2026-06-08 12:53:26.524531 | 
2026-06-08 12:53:26.524733 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-06-08 12:53:26.975903 | localhost -> localhost | changed
2026-06-08 12:53:26.980493 | 
2026-06-08 12:53:26.980602 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-06-08 12:53:27.956735 | localhost -> localhost | changed
2026-06-08 12:53:27.963791 | 
2026-06-08 12:53:27.963927 | TASK [Setup log path fact]
2026-06-08 12:53:27.987885 | localhost | ok
2026-06-08 12:53:28.007690 | 
2026-06-08 12:53:28.007896 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 12:53:28.048983 | localhost | ok
2026-06-08 12:53:28.060152 | 
2026-06-08 12:53:28.060320 | TASK [emit-job-header : Print job information]
2026-06-08 12:53:28.112083 | # Job Information
2026-06-08 12:53:28.112364 | Ansible Version: 2.16.18
2026-06-08 12:53:28.112418 | Job: cifmw-molecule-bm_sno
2026-06-08 12:53:28.112459 | Pipeline: github-check
2026-06-08 12:53:28.112496 | Executor: 38.102.83.40
2026-06-08 12:53:28.112533 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3971
2026-06-08 12:53:28.112604 | Log URL (when completed): https://gateway-cloud-softwarefactory.apps.ocp.cloud.ci.centos.org/logs/bc4/rdoproject.org/bc42071673f54606b8bae9f0aa265917/
2026-06-08 12:53:28.112657 | Event ID: ad7c5100-6338-11f1-9b2b-806eedc7b185
2026-06-08 12:53:28.119722 | 
2026-06-08 12:53:28.119853 | LOOP [emit-job-header : Print node information]
2026-06-08 12:53:28.228012 | localhost | ok:
2026-06-08 12:53:28.228294 | localhost | # Node Information
2026-06-08 12:53:28.228338 | localhost | Inventory Hostname: controller
2026-06-08 12:53:28.228373 | localhost | Hostname: np0000067252
2026-06-08 12:53:28.228403 | localhost | Username: zuul
2026-06-08 12:53:28.228435 | localhost | Distro: CentOS 9
2026-06-08 12:53:28.228464 | localhost | Provider: vexxhost-nodepool-tripleo
2026-06-08 12:53:28.228492 | localhost | Region: RegionOne
2026-06-08 12:53:28.228520 | localhost | Label: cloud-centos-9-stream-tripleo
2026-06-08 12:53:28.228547 | localhost | Product Name: OpenStack Nova
2026-06-08 12:53:28.228597 | localhost | Interface IP: 38.102.83.36
2026-06-08 12:53:28.247029 | 
2026-06-08 12:53:28.247154 | PLAY [all]
2026-06-08 12:53:28.257996 | 
2026-06-08 12:53:28.258129 | TASK [Gather network facts]
2026-06-08 12:53:28.678928 | controller | ok
2026-06-08 12:53:28.690457 | 
2026-06-08 12:53:28.690618 | TASK [include_role : start-zuul-console]
2026-06-08 12:53:28.715440 | controller | ok
2026-06-08 12:53:28.733490 | 
2026-06-08 12:53:28.733680 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-06-08 12:53:29.130499 | controller | ok
2026-06-08 12:53:29.139602 | 
2026-06-08 12:53:29.139722 | TASK [include_role : add-build-sshkey]
2026-06-08 12:53:29.171242 | controller | ok
2026-06-08 12:53:29.186402 | 
2026-06-08 12:53:29.186501 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-06-08 12:53:29.476772 | controller -> localhost | ok
2026-06-08 12:53:29.482757 | 
2026-06-08 12:53:29.482888 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-06-08 12:53:29.503469 | controller | ok
2026-06-08 12:53:29.516202 | controller | included: /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-06-08 12:53:29.520775 | 
2026-06-08 12:53:29.520852 | TASK [add-build-sshkey : Create Temp SSH key]
2026-06-08 12:53:30.386479 | controller -> localhost | Generating public/private rsa key pair.
2026-06-08 12:53:30.386714 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/bc42071673f54606b8bae9f0aa265917_id_rsa
2026-06-08 12:53:30.386745 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/bc42071673f54606b8bae9f0aa265917_id_rsa.pub
2026-06-08 12:53:30.386766 | controller -> localhost | The key fingerprint is:
2026-06-08 12:53:30.386785 | controller -> localhost | SHA256:2js44zQ0b0EiS6i/JBIet14kbXu1DaHoSTJrRPYy5Yo zuul-build-sshkey
2026-06-08 12:53:30.386804 | controller -> localhost | The key's randomart image is:
2026-06-08 12:53:30.386822 | controller -> localhost | +---[RSA 3072]----+
2026-06-08 12:53:30.386839 | controller -> localhost | |                 |
2026-06-08 12:53:30.386858 | controller -> localhost | |   .             |
2026-06-08 12:53:30.386877 | controller -> localhost | |  .oo.. ..       |
2026-06-08 12:53:30.386895 | controller -> localhost | | .o.=o.o. .      |
2026-06-08 12:53:30.386912 | controller -> localhost | |o. O.Oo.So       |
2026-06-08 12:53:30.386930 | controller -> localhost | |.o= #.o=..+      |
2026-06-08 12:53:30.386947 | controller -> localhost | |oEo= =+o+. .     |
2026-06-08 12:53:30.386965 | controller -> localhost | |.oo...=o..       |
2026-06-08 12:53:30.386982 | controller -> localhost | |  .. ..o..       |
2026-06-08 12:53:30.386999 | controller -> localhost | +----[SHA256]-----+
2026-06-08 12:53:30.387041 | controller -> localhost | ok: Runtime: 0:00:00.392435
2026-06-08 12:53:30.390473 | 
2026-06-08 12:53:30.390532 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-06-08 12:53:30.417481 | controller | ok
2026-06-08 12:53:30.425379 | controller | included: /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-06-08 12:53:30.431730 | 
2026-06-08 12:53:30.431789 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-06-08 12:53:30.456427 | controller | skipping: Conditional result was False
2026-06-08 12:53:30.461153 | 
2026-06-08 12:53:30.461228 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-06-08 12:53:31.007229 | controller | changed
2026-06-08 12:53:31.015080 | 
2026-06-08 12:53:31.015220 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-06-08 12:53:31.283199 | controller | ok
2026-06-08 12:53:31.290761 | 
2026-06-08 12:53:31.290895 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-06-08 12:53:32.102836 | controller | changed
2026-06-08 12:53:32.110150 | 
2026-06-08 12:53:32.110280 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-06-08 12:53:32.934180 | controller | changed
2026-06-08 12:53:32.941626 | 
2026-06-08 12:53:32.941756 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-06-08 12:53:32.978503 | controller | skipping: Conditional result was False
2026-06-08 12:53:32.989150 | 
2026-06-08 12:53:32.989385 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-06-08 12:53:33.482919 | controller -> localhost | changed
2026-06-08 12:53:33.497970 | 
2026-06-08 12:53:33.498105 | TASK [add-build-sshkey : Add back temp key]
2026-06-08 12:53:33.859330 | controller -> localhost | Identity added: /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/bc42071673f54606b8bae9f0aa265917_id_rsa (zuul-build-sshkey)
2026-06-08 12:53:33.859617 | controller -> localhost | ok: Runtime: 0:00:00.018468
2026-06-08 12:53:33.864769 | 
2026-06-08 12:53:33.864851 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-06-08 12:53:34.240560 | controller | ok
2026-06-08 12:53:34.245304 | 
2026-06-08 12:53:34.245377 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-06-08 12:53:34.284421 | controller | skipping: Conditional result was False
2026-06-08 12:53:34.293986 | 
2026-06-08 12:53:34.294113 | TASK [include_role : validate-host]
2026-06-08 12:53:34.330865 | controller | ok
2026-06-08 12:53:34.368378 | 
2026-06-08 12:53:34.368551 | TASK [validate-host : Define zuul_info_dir fact]
2026-06-08 12:53:34.407564 | controller | ok
2026-06-08 12:53:34.410809 | 
2026-06-08 12:53:34.410873 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-06-08 12:53:34.720638 | controller -> localhost | ok
2026-06-08 12:53:34.731803 | 
2026-06-08 12:53:34.732071 | TASK [validate-host : Collect information about the host]
2026-06-08 12:53:35.428972 | controller | ok
2026-06-08 12:53:35.444877 | 
2026-06-08 12:53:35.445084 | TASK [validate-host : Sanitize hostname]
2026-06-08 12:53:35.530007 | controller | ok
2026-06-08 12:53:35.538082 | 
2026-06-08 12:53:35.538220 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-06-08 12:53:36.113533 | controller -> localhost | changed
2026-06-08 12:53:36.119743 | 
2026-06-08 12:53:36.119806 | TASK [validate-host : Collect information about zuul worker]
2026-06-08 12:53:36.547151 | controller | ok
2026-06-08 12:53:36.554790 | 
2026-06-08 12:53:36.554927 | TASK [validate-host : Write out all zuul information for each host]
2026-06-08 12:53:37.099026 | controller -> localhost | changed
2026-06-08 12:53:37.113322 | 
2026-06-08 12:53:37.113448 | TASK [include_role : prepare-workspace-openshift]
2026-06-08 12:53:37.129226 | controller | skipping: Conditional result was False
2026-06-08 12:53:37.133253 | 
2026-06-08 12:53:37.133346 | TASK [include_role : remove-zuul-sshkey]
2026-06-08 12:53:37.157012 | controller | skipping: Conditional result was False
2026-06-08 12:53:37.161144 | 
2026-06-08 12:53:37.161215 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-06-08 12:53:37.415373 | controller | ok: "logs"
2026-06-08 12:53:37.415910 | controller | ok: All items complete
2026-06-08 12:53:37.415974 | 
2026-06-08 12:53:37.614656 | controller | ok: "artifacts"
2026-06-08 12:53:37.832699 | controller | ok: "docs"
2026-06-08 12:53:37.852335 | 
2026-06-08 12:53:37.852539 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-06-08 12:53:38.104000 | controller | changed: "logs"
2026-06-08 12:53:38.323760 | controller | changed: "artifacts"
2026-06-08 12:53:38.558147 | controller | changed: "docs"
2026-06-08 12:53:38.579292 | 
2026-06-08 12:53:38.579465 | PLAY RECAP
2026-06-08 12:53:38.579555 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 12:53:38.579658 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 12:53:38.579699 | 
2026-06-08 12:53:38.745509 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-06-08 12:53:38.747863 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 12:53:39.460980 | 
2026-06-08 12:53:39.461091 | PLAY [all]
2026-06-08 12:53:39.471098 | 
2026-06-08 12:53:39.471174 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 12:53:39.553178 | controller | ok
2026-06-08 12:53:39.560729 | 
2026-06-08 12:53:39.560885 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 12:53:40.032286 | controller | changed
2026-06-08 12:53:40.042127 | 
2026-06-08 12:53:40.042264 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 12:53:41.140798 | controller | changed
2026-06-08 12:53:41.151558 | 
2026-06-08 12:53:41.151676 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-06-08 12:53:41.651527 | controller | changed:
2026-06-08 12:53:41.651893 | controller | {
2026-06-08 12:53:41.651950 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-06-08 12:53:41.652007 | controller | }
2026-06-08 12:53:41.937973 | controller | changed:
2026-06-08 12:53:41.938166 | controller | {
2026-06-08 12:53:41.938223 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-06-08 12:53:41.938267 | controller | }
2026-06-08 12:53:42.198817 | controller | changed:
2026-06-08 12:53:42.199125 | controller | {
2026-06-08 12:53:42.199192 | 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 12:53:42.199236 | controller | }
2026-06-08 12:53:42.471178 | controller | changed:
2026-06-08 12:53:42.471395 | controller | {
2026-06-08 12:53:42.471452 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-06-08 12:53:42.471494 | controller | }
2026-06-08 12:53:42.742207 | controller | changed:
2026-06-08 12:53:42.742520 | controller | {
2026-06-08 12:53:42.742645 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-06-08 12:53:42.742711 | controller | }
2026-06-08 12:53:42.979879 | controller | changed:
2026-06-08 12:53:42.980071 | controller | {
2026-06-08 12:53:42.980122 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-06-08 12:53:42.980162 | controller | }
2026-06-08 12:53:43.229693 | controller | changed:
2026-06-08 12:53:43.229885 | controller | {
2026-06-08 12:53:43.229934 | 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 12:53:43.229975 | controller | }
2026-06-08 12:53:43.505016 | controller | changed:
2026-06-08 12:53:43.505281 | controller | {
2026-06-08 12:53:43.505344 | 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 12:53:43.505403 | controller | }
2026-06-08 12:53:43.780144 | controller | changed:
2026-06-08 12:53:43.780445 | controller | {
2026-06-08 12:53:43.780520 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-06-08 12:53:43.780571 | controller | }
2026-06-08 12:53:44.033024 | controller | changed:
2026-06-08 12:53:44.033224 | controller | {
2026-06-08 12:53:44.033277 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-06-08 12:53:44.033319 | controller | }
2026-06-08 12:53:44.297523 | controller | changed:
2026-06-08 12:53:44.297839 | controller | {
2026-06-08 12:53:44.297899 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-06-08 12:53:44.297939 | controller | }
2026-06-08 12:53:44.532608 | controller | changed:
2026-06-08 12:53:44.532853 | controller | {
2026-06-08 12:53:44.532928 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-06-08 12:53:44.532976 | controller | }
2026-06-08 12:53:44.790926 | controller | changed:
2026-06-08 12:53:44.791112 | controller | {
2026-06-08 12:53:44.791192 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-06-08 12:53:44.791262 | controller | }
2026-06-08 12:53:45.116002 | controller | changed:
2026-06-08 12:53:45.116173 | controller | {
2026-06-08 12:53:45.116225 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-06-08 12:53:45.116266 | controller | }
2026-06-08 12:53:45.346845 | controller | changed:
2026-06-08 12:53:45.347038 | controller | {
2026-06-08 12:53:45.347099 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-06-08 12:53:45.347262 | controller | }
2026-06-08 12:53:45.626383 | controller | changed:
2026-06-08 12:53:45.626533 | controller | {
2026-06-08 12:53:45.626609 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-06-08 12:53:45.626657 | controller | }
2026-06-08 12:53:45.911565 | controller | changed:
2026-06-08 12:53:45.911754 | controller | {
2026-06-08 12:53:45.911806 | 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 12:53:45.911846 | controller | }
2026-06-08 12:53:46.179051 | controller | changed:
2026-06-08 12:53:46.179372 | controller | {
2026-06-08 12:53:46.179434 | 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 12:53:46.179496 | controller | }
2026-06-08 12:53:46.428042 | controller | changed:
2026-06-08 12:53:46.428242 | controller | {
2026-06-08 12:53:46.428310 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-06-08 12:53:46.428360 | controller | }
2026-06-08 12:53:46.676965 | controller | changed:
2026-06-08 12:53:46.677134 | controller | {
2026-06-08 12:53:46.677182 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-06-08 12:53:46.677225 | controller | }
2026-06-08 12:53:46.928974 | controller | changed:
2026-06-08 12:53:46.929150 | controller | {
2026-06-08 12:53:46.929199 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-06-08 12:53:46.929238 | controller | }
2026-06-08 12:53:47.208950 | controller | changed:
2026-06-08 12:53:47.209123 | controller | {
2026-06-08 12:53:47.209170 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-06-08 12:53:47.209208 | controller | }
2026-06-08 12:53:47.509230 | controller | changed:
2026-06-08 12:53:47.509384 | controller | {
2026-06-08 12:53:47.509433 | 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 12:53:47.509505 | controller | }
2026-06-08 12:53:47.766205 | controller | changed:
2026-06-08 12:53:47.766440 | controller | {
2026-06-08 12:53:47.766496 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-06-08 12:53:47.766537 | controller | }
2026-06-08 12:53:48.031302 | controller | changed:
2026-06-08 12:53:48.031473 | controller | {
2026-06-08 12:53:48.031524 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-06-08 12:53:48.031565 | controller | }
2026-06-08 12:53:48.269971 | controller | changed:
2026-06-08 12:53:48.270171 | controller | {
2026-06-08 12:53:48.270220 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-06-08 12:53:48.270259 | controller | }
2026-06-08 12:53:48.307420 | 
2026-06-08 12:53:48.307654 | TASK [Set timezone to UTC]
2026-06-08 12:53:48.798672 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-06-08 12:53:48.805886 | 
2026-06-08 12:53:48.806014 | TASK [Create nodepool directory]
2026-06-08 12:53:49.113191 | controller | changed
2026-06-08 12:53:49.123196 | 
2026-06-08 12:53:49.123324 | TASK [Create nodepool sub_nodes file]
2026-06-08 12:53:49.924328 | controller | changed
2026-06-08 12:53:49.929687 | 
2026-06-08 12:53:49.929770 | TASK [Create nodepool sub_nodes_private file]
2026-06-08 12:53:50.624407 | controller | changed
2026-06-08 12:53:50.632479 | 
2026-06-08 12:53:50.632638 | LOOP [Populate nodepool sub_nodes file]
2026-06-08 12:53:50.678123 | 
2026-06-08 12:53:50.678411 | LOOP [Populate nodepool sub_nodes_private file]
2026-06-08 12:53:50.723485 | 
2026-06-08 12:53:50.723877 | TASK [Create nodepool primary file]
2026-06-08 12:53:50.749876 | controller | skipping: Conditional result was False
2026-06-08 12:53:50.758648 | 
2026-06-08 12:53:50.758777 | TASK [Create nodepool node_private for this node]
2026-06-08 12:53:51.470486 | controller | changed
2026-06-08 12:53:51.476642 | 
2026-06-08 12:53:51.476720 | LOOP [Copy ssh keys to nodepool directory]
2026-06-08 12:53:51.888264 | controller | ok: Item: id_rsa Runtime: 0:00:00.006393
2026-06-08 12:53:51.888464 | 
2026-06-08 12:53:52.108872 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006595
2026-06-08 12:53:52.126794 | 
2026-06-08 12:53:52.126946 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-06-08 12:53:52.833159 | controller | changed
2026-06-08 12:53:52.840136 | 
2026-06-08 12:53:52.840265 | TASK [Validate sudoers config after edits]
2026-06-08 12:53:53.102147 | controller | /etc/sudoers: parsed OK
2026-06-08 12:53:53.102209 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-06-08 12:53:53.102215 | controller | /etc/sudoers.d/zuul: parsed OK
2026-06-08 12:53:53.102219 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-06-08 12:53:53.381884 | controller | ok: Runtime: 0:00:00.007631
2026-06-08 12:53:53.390801 | 
2026-06-08 12:53:53.390930 | TASK [Show the environment passed in to job shell scripts]
2026-06-08 12:53:53.664566 | controller | SHELL=/bin/bash
2026-06-08 12:53:53.664639 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-06-08 12:53:53.664769 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-06-08 12:53:53.664782 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/71/3971/59abffa59e3343907eee97da90f4037d922d425a
2026-06-08 12:53:53.664790 | controller | PWD=/home/zuul
2026-06-08 12:53:53.664795 | controller | ZUUL_PIPELINE=github-check
2026-06-08 12:53:53.664803 | controller | LOGNAME=zuul
2026-06-08 12:53:53.664808 | controller | XDG_SESSION_TYPE=tty
2026-06-08 12:53:53.664813 | controller | _=/usr/bin/env
2026-06-08 12:53:53.664820 | controller | MOTD_SHOWN=pam
2026-06-08 12:53:53.664825 | controller | HOME=/home/zuul
2026-06-08 12:53:53.664830 | controller | LANG=en_US.UTF-8
2026-06-08 12:53:53.664835 | controller | SSH_CONNECTION=38.102.83.40 54144 38.102.83.36 22
2026-06-08 12:53:53.664841 | 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 12:53:53.664847 | controller | ZUUL_CHANGE_IDS=3971,59abffa59e3343907eee97da90f4037d922d425a
2026-06-08 12:53:53.664853 | controller | WORKSPACE=/home/zuul/workspace
2026-06-08 12:53:53.664858 | controller | XDG_SESSION_CLASS=user
2026-06-08 12:53:53.664862 | controller | SELINUX_ROLE_REQUESTED=
2026-06-08 12:53:53.664867 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-06-08 12:53:53.664872 | controller | USER=zuul
2026-06-08 12:53:53.664877 | controller | ZUUL_VOTING=True
2026-06-08 12:53:53.664882 | controller | BUILD_TIMEOUT=1800000
2026-06-08 12:53:53.664887 | controller | SELINUX_USE_CURRENT_RANGE=
2026-06-08 12:53:53.664892 | controller | SHLVL=1
2026-06-08 12:53:53.664897 | controller | ZUUL_PATCHSET=59abffa59e3343907eee97da90f4037d922d425a
2026-06-08 12:53:53.664902 | controller | XDG_SESSION_ID=1
2026-06-08 12:53:53.664907 | controller | ZUUL_BRANCH=main
2026-06-08 12:53:53.664911 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-06-08 12:53:53.664915 | controller | SSH_CLIENT=38.102.83.40 54144 22
2026-06-08 12:53:53.664922 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-06-08 12:53:53.664926 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-06-08 12:53:53.664929 | controller | which_declare=declare -f
2026-06-08 12:53:53.664933 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2026-06-08 12:53:53.664937 | controller | SELINUX_LEVEL_REQUESTED=
2026-06-08 12:53:53.664940 | controller | ZUUL_CHANGE=3971
2026-06-08 12:53:53.664944 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-06-08 12:53:53.664947 | controller | ZUUL_UUID=bc42071673f54606b8bae9f0aa265917
2026-06-08 12:53:53.664966 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-06-08 12:53:53.664973 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-06-08 12:53:53.664977 | controller | }
2026-06-08 12:53:53.934023 | controller | ok: Runtime: 0:00:00.012298
2026-06-08 12:53:53.943316 | 
2026-06-08 12:53:53.943461 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-06-08 12:53:53.969652 | controller | skipping: Conditional result was False
2026-06-08 12:53:53.978514 | 
2026-06-08 12:53:53.978676 | TASK [Symlink /home/zuul-worker/workspace]
2026-06-08 12:53:54.518912 | controller | skipping: Conditional result was False
2026-06-08 12:53:54.527919 | 
2026-06-08 12:53:54.528047 | TASK [Ensure legacy workspace directory]
2026-06-08 12:53:54.826733 | controller | changed
2026-06-08 12:53:54.829556 | 
2026-06-08 12:53:54.829712 | PLAY RECAP
2026-06-08 12:53:54.829801 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-06-08 12:53:54.829847 | 
2026-06-08 12:53:55.005032 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-06-08 12:53:55.008621 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 12:53:55.614278 | 
2026-06-08 12:53:55.614405 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-06-08 12:53:55.625201 | 
2026-06-08 12:53:55.625290 | TASK [Create zuul-output directory]
2026-06-08 12:53:56.026979 | controller | changed
2026-06-08 12:53:56.036958 | 
2026-06-08 12:53:56.037222 | TASK [Slurp Zuul inventory test]
2026-06-08 12:53:56.465428 | controller -> localhost | ok
2026-06-08 12:53:56.478627 | 
2026-06-08 12:53:56.478781 | TASK [Save zuul inventory]
2026-06-08 12:53:57.537950 | controller | changed
2026-06-08 12:53:57.548436 | 
2026-06-08 12:53:57.548801 | TASK [Save zuul vars without the change_message]
2026-06-08 12:53:58.325976 | controller | changed
2026-06-08 12:53:58.328849 | 
2026-06-08 12:53:58.328946 | PLAY RECAP
2026-06-08 12:53:58.329027 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-06-08 12:53:58.329069 | 
2026-06-08 12:53:58.458781 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-06-08 12:53:58.460411 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 12:53:59.197916 | 
2026-06-08 12:53:59.198046 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-06-08 12:53:59.209804 | 
2026-06-08 12:53:59.209890 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-06-08 12:53:59.238053 | controller | ok
2026-06-08 12:53:59.252101 | 
2026-06-08 12:53:59.252176 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-06-08 12:53:59.296683 | controller | skipping: Conditional result was False
2026-06-08 12:53:59.301529 | 
2026-06-08 12:53:59.301617 | TASK [mirror-info-fork : Create /etc/ci]
2026-06-08 12:53:59.712706 | controller | ok
2026-06-08 12:53:59.722777 | 
2026-06-08 12:53:59.722921 | TASK [mirror-info-fork : Install ci_mirror script]
2026-06-08 12:54:00.590919 | controller | ok
2026-06-08 12:54:00.606176 | 
2026-06-08 12:54:00.606351 | TASK [Prepare workspace]
2026-06-08 12:54:00.632007 | controller | ok
2026-06-08 12:54:00.665761 | 
2026-06-08 12:54:00.665917 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-06-08 12:54:01.072736 | controller | ok
2026-06-08 12:54:01.079656 | 
2026-06-08 12:54:01.079755 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-06-08 12:54:03.133645 | controller | Output suppressed because no_log was given
2026-06-08 12:54:03.140197 | 
2026-06-08 12:54:03.140288 | LOOP [Create zuul-output directory]
2026-06-08 12:54:03.391006 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-06-08 12:54:03.583046 | controller | ok: "/home/zuul/zuul-output/logs"
2026-06-08 12:54:03.601188 | 
2026-06-08 12:54:03.601390 | TASK [Install required packages]
2026-06-08 12:54:53.769910 | controller | changed
2026-06-08 12:54:53.778922 | 
2026-06-08 12:54:53.779048 | TASK [Install venv]
2026-06-08 12:56:04.929630 | controller | changed
2026-06-08 12:56:04.949407 | 
2026-06-08 12:56:04.949512 | PLAY RECAP
2026-06-08 12:56:04.949630 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 12:56:04.949776 | 
2026-06-08 12:56:05.102082 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-06-08 12:56:05.105286 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 12:56:05.735446 | 
2026-06-08 12:56:05.735593 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-06-08 12:56:05.747341 | 
2026-06-08 12:56:05.747447 | TASK [Gather required facts]
2026-06-08 12:56:06.401891 | controller | ok
2026-06-08 12:56:06.411003 | 
2026-06-08 12:56:06.411162 | TASK [Load environment var if instructed to]
2026-06-08 12:56:06.448132 | controller | skipping: Conditional result was False
2026-06-08 12:56:06.457327 | 
2026-06-08 12:56:06.457498 | TASK [Ensure group_vars dir exists]
2026-06-08 12:56:06.892547 | controller | ok
2026-06-08 12:56:06.900812 | 
2026-06-08 12:56:06.900947 | TASK [Print related variables]
2026-06-08 12:56:06.944653 | controller | ok:
2026-06-08 12:56:06.944874 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-06-08 12:56:06.944929 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/bm_sno
2026-06-08 12:56:06.952066 | 
2026-06-08 12:56:06.952197 | TASK [Run molecule]
2026-06-08 12:56:08.209344 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-06-08 12:56:08.309134 | controller | INFO     Running bm_redfish > prepare
2026-06-08 12:56:09.163581 | controller |
2026-06-08 12:56:09.163809 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-06-08 12:56:09.164026 | controller |
2026-06-08 12:56:09.164204 | controller | TASK [Create mock server directory] ********************************************
2026-06-08 12:56:09.164910 | controller | Monday 08 June 2026  12:56:09 +0000 (0:00:00.033)       0:00:00.033 ***********
2026-06-08 12:56:09.580561 | controller | changed: [instance]
2026-06-08 12:56:09.580610 | controller |
2026-06-08 12:56:09.580618 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-06-08 12:56:09.580623 | controller | Monday 08 June 2026  12:56:09 +0000 (0:00:00.418)       0:00:00.451 ***********
2026-06-08 12:56:10.064605 | controller | changed: [instance]
2026-06-08 12:56:10.064644 | controller |
2026-06-08 12:56:10.064650 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-06-08 12:56:10.064655 | controller | Monday 08 June 2026  12:56:10 +0000 (0:00:00.484)       0:00:00.935 ***********
2026-06-08 12:56:10.715946 | controller | changed: [instance]
2026-06-08 12:56:10.716028 | controller |
2026-06-08 12:56:10.716034 | controller | TASK [Start mock iDRAC server] *************************************************
2026-06-08 12:56:10.716039 | controller | Monday 08 June 2026  12:56:10 +0000 (0:00:00.650)       0:00:01.586 ***********
2026-06-08 12:56:10.933180 | controller | changed: [instance]
2026-06-08 12:56:10.933248 | controller |
2026-06-08 12:56:10.933255 | controller | TASK [Record mock server PID] **************************************************
2026-06-08 12:56:10.933278 | controller | Monday 08 June 2026  12:56:10 +0000 (0:00:00.217)       0:00:01.803 ***********
2026-06-08 12:56:11.170586 | controller | ok: [instance]
2026-06-08 12:56:11.170732 | controller |
2026-06-08 12:56:11.170739 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-06-08 12:56:11.170745 | controller | Monday 08 June 2026  12:56:11 +0000 (0:00:00.237)       0:00:02.041 ***********
2026-06-08 12:56:11.689136 | controller | ok: [instance]
2026-06-08 12:56:11.689231 | controller |
2026-06-08 12:56:11.689236 | controller | PLAY RECAP *********************************************************************
2026-06-08 12:56:11.689250 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 12:56:11.689531 | controller |
2026-06-08 12:56:11.689675 | controller | Monday 08 June 2026  12:56:11 +0000 (0:00:00.518)       0:00:02.560 ***********
2026-06-08 12:56:11.689826 | controller | ===============================================================================
2026-06-08 12:56:11.690060 | controller | Copy mock iDRAC server script ------------------------------------------- 0.65s
2026-06-08 12:56:11.690246 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.52s
2026-06-08 12:56:11.690407 | controller | Generate self-signed TLS certificate ------------------------------------ 0.48s
2026-06-08 12:56:11.690557 | controller | Create mock server directory -------------------------------------------- 0.42s
2026-06-08 12:56:11.690715 | controller | Record mock server PID -------------------------------------------------- 0.24s
2026-06-08 12:56:11.690912 | controller | Start mock iDRAC server ------------------------------------------------- 0.22s
2026-06-08 12:56:11.786399 | controller | INFO     Running bm_redfish > converge
2026-06-08 12:56:12.347728 | controller |
2026-06-08 12:56:12.347795 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-06-08 12:56:12.347880 | controller |
2026-06-08 12:56:12.348101 | controller | TASK [Test bm_power_off] *******************************************************
2026-06-08 12:56:12.348202 | controller | Monday 08 June 2026  12:56:12 +0000 (0:00:00.056)       0:00:00.056 ***********
2026-06-08 12:56:12.370598 | 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 12:56:12.370683 | controller |
2026-06-08 12:56:12.370746 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 12:56:12.370866 | controller | Monday 08 June 2026  12:56:12 +0000 (0:00:00.023)       0:00:00.080 ***********
2026-06-08 12:56:12.862752 | controller | ok: [instance]
2026-06-08 12:56:12.862854 | controller |
2026-06-08 12:56:12.862863 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 12:56:12.862971 | controller | Monday 08 June 2026  12:56:12 +0000 (0:00:00.492)       0:00:00.573 ***********
2026-06-08 12:56:12.890624 | controller |
2026-06-08 12:56:12.890724 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:12.890732 | controller | Monday 08 June 2026  12:56:12 +0000 (0:00:00.027)       0:00:00.600 ***********
2026-06-08 12:56:13.251625 | controller | ok: [instance]
2026-06-08 12:56:13.251681 | controller |
2026-06-08 12:56:13.251840 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 12:56:13.252026 | controller | Monday 08 June 2026  12:56:13 +0000 (0:00:00.360)       0:00:00.961 ***********
2026-06-08 12:56:13.269404 | controller | skipping: [instance]
2026-06-08 12:56:13.269456 | controller |
2026-06-08 12:56:13.269569 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 12:56:13.269667 | controller | Monday 08 June 2026  12:56:13 +0000 (0:00:00.018)       0:00:00.979 ***********
2026-06-08 12:56:13.291796 | controller | skipping: [instance]
2026-06-08 12:56:13.291892 | controller |
2026-06-08 12:56:13.292017 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-06-08 12:56:13.292117 | controller | Monday 08 June 2026  12:56:13 +0000 (0:00:00.022)       0:00:01.002 ***********
2026-06-08 12:56:13.670526 | controller | ok: [instance]
2026-06-08 12:56:13.670892 | controller |
2026-06-08 12:56:13.670939 | controller | TASK [Assert host is still Off] ************************************************
2026-06-08 12:56:13.670947 | controller | Monday 08 June 2026  12:56:13 +0000 (0:00:00.378)       0:00:01.380 ***********
2026-06-08 12:56:13.698893 | controller | ok: [instance] => {
2026-06-08 12:56:13.698934 | controller |     "changed": false,
2026-06-08 12:56:13.698939 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:13.698944 | controller | }
2026-06-08 12:56:13.698948 | controller |
2026-06-08 12:56:13.698969 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 12:56:13.698977 | controller | Monday 08 June 2026  12:56:13 +0000 (0:00:00.027)       0:00:01.408 ***********
2026-06-08 12:56:14.048237 | controller | ok: [instance]
2026-06-08 12:56:14.048299 | controller |
2026-06-08 12:56:14.048781 | controller | TASK [Include bm_power_off] ****************************************************
2026-06-08 12:56:14.048838 | controller | Monday 08 June 2026  12:56:14 +0000 (0:00:00.349)       0:00:01.757 ***********
2026-06-08 12:56:14.085888 | controller |
2026-06-08 12:56:14.086129 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:14.086274 | controller | Monday 08 June 2026  12:56:14 +0000 (0:00:00.037)       0:00:01.795 ***********
2026-06-08 12:56:14.411092 | controller | ok: [instance]
2026-06-08 12:56:14.411129 | controller |
2026-06-08 12:56:14.411134 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 12:56:14.411142 | controller | Monday 08 June 2026  12:56:14 +0000 (0:00:00.325)       0:00:02.120 ***********
2026-06-08 12:56:14.745111 | controller | ok: [instance]
2026-06-08 12:56:14.745196 | controller |
2026-06-08 12:56:14.745201 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 12:56:14.745206 | controller | Monday 08 June 2026  12:56:14 +0000 (0:00:00.334)       0:00:02.455 ***********
2026-06-08 12:56:15.110181 | controller | ok: [instance]
2026-06-08 12:56:15.110218 | controller |
2026-06-08 12:56:15.110224 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-06-08 12:56:15.110236 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.365)       0:00:02.820 ***********
2026-06-08 12:56:15.485668 | controller | ok: [instance]
2026-06-08 12:56:15.485719 | controller |
2026-06-08 12:56:15.485729 | controller | TASK [Assert host is now Off] **************************************************
2026-06-08 12:56:15.485737 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.375)       0:00:03.195 ***********
2026-06-08 12:56:15.511145 | controller | ok: [instance] => {
2026-06-08 12:56:15.511191 | controller |     "changed": false,
2026-06-08 12:56:15.511198 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:15.511894 | controller | }
2026-06-08 12:56:15.511938 | controller |
2026-06-08 12:56:15.511949 | controller | TASK [Test bm_power_on] ********************************************************
2026-06-08 12:56:15.512003 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.025)       0:00:03.220 ***********
2026-06-08 12:56:15.544848 | 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 12:56:15.545308 | controller |
2026-06-08 12:56:15.545742 | controller | TASK [Reset mock to power On] **************************************************
2026-06-08 12:56:15.546168 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.034)       0:00:03.254 ***********
2026-06-08 12:56:15.920145 | controller | ok: [instance]
2026-06-08 12:56:15.920189 | controller |
2026-06-08 12:56:15.920623 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 12:56:15.920672 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.375)       0:00:03.630 ***********
2026-06-08 12:56:15.951135 | controller |
2026-06-08 12:56:15.951503 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:15.951551 | controller | Monday 08 June 2026  12:56:15 +0000 (0:00:00.030)       0:00:03.661 ***********
2026-06-08 12:56:16.320889 | controller | ok: [instance]
2026-06-08 12:56:16.320936 | controller |
2026-06-08 12:56:16.320947 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 12:56:16.320985 | controller | Monday 08 June 2026  12:56:16 +0000 (0:00:00.368)       0:00:04.030 ***********
2026-06-08 12:56:16.350586 | controller | skipping: [instance]
2026-06-08 12:56:16.350633 | controller |
2026-06-08 12:56:16.350641 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 12:56:16.350650 | controller | Monday 08 June 2026  12:56:16 +0000 (0:00:00.029)       0:00:04.060 ***********
2026-06-08 12:56:16.736397 | controller | ok: [instance]
2026-06-08 12:56:16.736638 | controller |
2026-06-08 12:56:16.736823 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 12:56:16.737027 | controller | Monday 08 June 2026  12:56:16 +0000 (0:00:00.386)       0:00:04.446 ***********
2026-06-08 12:56:16.781271 | controller | ok: [instance] => {
2026-06-08 12:56:16.781445 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 12:56:16.781573 | controller | }
2026-06-08 12:56:16.781698 | controller |
2026-06-08 12:56:16.781831 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-06-08 12:56:16.781983 | controller | Monday 08 June 2026  12:56:16 +0000 (0:00:00.044)       0:00:04.491 ***********
2026-06-08 12:56:17.142804 | controller | ok: [instance]
2026-06-08 12:56:17.143011 | controller |
2026-06-08 12:56:17.143152 | controller | TASK [Assert host is still On with POST complete] ******************************
2026-06-08 12:56:17.143284 | controller | Monday 08 June 2026  12:56:17 +0000 (0:00:00.360)       0:00:04.852 ***********
2026-06-08 12:56:17.179331 | controller | ok: [instance] => {
2026-06-08 12:56:17.179503 | controller |     "changed": false,
2026-06-08 12:56:17.179639 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:17.179767 | controller | }
2026-06-08 12:56:17.179885 | controller |
2026-06-08 12:56:17.180030 | controller | TASK [Reset mock to power Off] *************************************************
2026-06-08 12:56:17.180160 | controller | Monday 08 June 2026  12:56:17 +0000 (0:00:00.037)       0:00:04.889 ***********
2026-06-08 12:56:17.564865 | controller | ok: [instance]
2026-06-08 12:56:17.565110 | controller |
2026-06-08 12:56:17.565277 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 12:56:17.565417 | controller | Monday 08 June 2026  12:56:17 +0000 (0:00:00.385)       0:00:05.274 ***********
2026-06-08 12:56:17.609485 | controller |
2026-06-08 12:56:17.609681 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:17.609826 | controller | Monday 08 June 2026  12:56:17 +0000 (0:00:00.044)       0:00:05.319 ***********
2026-06-08 12:56:17.979866 | controller | ok: [instance]
2026-06-08 12:56:17.980128 | controller |
2026-06-08 12:56:17.980305 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 12:56:17.980454 | controller | Monday 08 June 2026  12:56:17 +0000 (0:00:00.370)       0:00:05.689 ***********
2026-06-08 12:56:18.388086 | controller | ok: [instance]
2026-06-08 12:56:18.388221 | controller |
2026-06-08 12:56:18.388305 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 12:56:18.388428 | controller | Monday 08 June 2026  12:56:18 +0000 (0:00:00.407)       0:00:06.097 ***********
2026-06-08 12:56:18.813544 | controller | ok: [instance]
2026-06-08 12:56:18.813823 | controller |
2026-06-08 12:56:18.814113 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 12:56:18.814375 | controller | Monday 08 June 2026  12:56:18 +0000 (0:00:00.425)       0:00:06.522 ***********
2026-06-08 12:56:18.864038 | controller | ok: [instance] => {
2026-06-08 12:56:18.864141 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 12:56:18.864280 | controller | }
2026-06-08 12:56:18.864401 | controller |
2026-06-08 12:56:18.864532 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-06-08 12:56:18.864683 | controller | Monday 08 June 2026  12:56:18 +0000 (0:00:00.050)       0:00:06.573 ***********
2026-06-08 12:56:19.238432 | controller | ok: [instance]
2026-06-08 12:56:19.238536 | controller |
2026-06-08 12:56:19.238671 | controller | TASK [Assert host is now On with POST complete] ********************************
2026-06-08 12:56:19.238793 | controller | Monday 08 June 2026  12:56:19 +0000 (0:00:00.372)       0:00:06.946 ***********
2026-06-08 12:56:19.262420 | controller | ok: [instance] => {
2026-06-08 12:56:19.262508 | controller |     "changed": false,
2026-06-08 12:56:19.262640 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:19.262747 | controller | }
2026-06-08 12:56:19.262854 | controller |
2026-06-08 12:56:19.262992 | controller | TASK [Reset mock to power Off without PostState support] ***********************
2026-06-08 12:56:19.263118 | controller | Monday 08 June 2026  12:56:19 +0000 (0:00:00.026)       0:00:06.972 ***********
2026-06-08 12:56:19.633505 | controller | ok: [instance]
2026-06-08 12:56:19.633599 | controller |
2026-06-08 12:56:19.633723 | controller | TASK [Include bm_power_on] *****************************************************
2026-06-08 12:56:19.633849 | controller | Monday 08 June 2026  12:56:19 +0000 (0:00:00.370)       0:00:07.343 ***********
2026-06-08 12:56:19.670614 | controller |
2026-06-08 12:56:19.670861 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:19.671116 | controller | Monday 08 June 2026  12:56:19 +0000 (0:00:00.036)       0:00:07.380 ***********
2026-06-08 12:56:20.170088 | controller | ok: [instance]
2026-06-08 12:56:20.170125 | controller |
2026-06-08 12:56:20.170138 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 12:56:20.170143 | controller | Monday 08 June 2026  12:56:20 +0000 (0:00:00.499)       0:00:07.879 ***********
2026-06-08 12:56:20.595464 | controller | ok: [instance]
2026-06-08 12:56:20.595499 | controller |
2026-06-08 12:56:20.595504 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 12:56:20.595509 | controller | Monday 08 June 2026  12:56:20 +0000 (0:00:00.425)       0:00:08.305 ***********
2026-06-08 12:56:20.973073 | controller | ok: [instance]
2026-06-08 12:56:20.973131 | controller |
2026-06-08 12:56:20.973137 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 12:56:20.973141 | controller | Monday 08 June 2026  12:56:20 +0000 (0:00:00.376)       0:00:08.682 ***********
2026-06-08 12:56:21.018325 | controller | ok: [instance] => {
2026-06-08 12:56:21.018379 | controller |     "msg": "POST state: not supported by firmware, used PowerState=On"
2026-06-08 12:56:21.019145 | controller | }
2026-06-08 12:56:21.019200 | controller |
2026-06-08 12:56:21.019211 | controller | TASK [Query mock state after power_on (no PostState)] **************************
2026-06-08 12:56:21.019221 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.045)       0:00:08.727 ***********
2026-06-08 12:56:21.406776 | controller | ok: [instance]
2026-06-08 12:56:21.406811 | controller |
2026-06-08 12:56:21.406820 | controller | TASK [Assert host is On (PostState stays null)] ********************************
2026-06-08 12:56:21.406826 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.389)       0:00:09.116 ***********
2026-06-08 12:56:21.435201 | controller | ok: [instance] => {
2026-06-08 12:56:21.435263 | controller |     "changed": false,
2026-06-08 12:56:21.435270 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:21.435698 | controller | }
2026-06-08 12:56:21.435752 | controller |
2026-06-08 12:56:21.435759 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-06-08 12:56:21.435764 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.028)       0:00:09.145 ***********
2026-06-08 12:56:21.470897 | 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 12:56:21.470932 | controller |
2026-06-08 12:56:21.470937 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-06-08 12:56:21.470942 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.035)       0:00:09.180 ***********
2026-06-08 12:56:21.820763 | controller | ok: [instance]
2026-06-08 12:56:21.820803 | controller |
2026-06-08 12:56:21.820810 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-06-08 12:56:21.820816 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.349)       0:00:09.529 ***********
2026-06-08 12:56:21.856040 | controller |
2026-06-08 12:56:21.856109 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 12:56:21.856117 | controller | Monday 08 June 2026  12:56:21 +0000 (0:00:00.035)       0:00:09.565 ***********
2026-06-08 12:56:22.206109 | controller | ok: [instance]
2026-06-08 12:56:22.206211 | controller |
2026-06-08 12:56:22.206217 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 12:56:22.206222 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.350)       0:00:09.916 ***********
2026-06-08 12:56:22.239130 | controller | ok: [instance]
2026-06-08 12:56:22.239173 | controller |
2026-06-08 12:56:22.239178 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 12:56:22.239186 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.032)       0:00:09.948 ***********
2026-06-08 12:56:22.276088 | controller | skipping: [instance]
2026-06-08 12:56:22.276275 | controller |
2026-06-08 12:56:22.276407 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-06-08 12:56:22.276570 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.037)       0:00:09.985 ***********
2026-06-08 12:56:22.318851 | controller | ok: [instance] => {
2026-06-08 12:56:22.318909 | controller |     "changed": false,
2026-06-08 12:56:22.319062 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:22.319148 | controller | }
2026-06-08 12:56:22.319252 | controller |
2026-06-08 12:56:22.319352 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 12:56:22.319499 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.043)       0:00:10.029 ***********
2026-06-08 12:56:22.695800 | controller | ok: [instance]
2026-06-08 12:56:22.696010 | controller |
2026-06-08 12:56:22.696303 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-06-08 12:56:22.696532 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.376)       0:00:10.405 ***********
2026-06-08 12:56:22.727405 | controller |
2026-06-08 12:56:22.727860 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 12:56:22.728126 | controller | Monday 08 June 2026  12:56:22 +0000 (0:00:00.032)       0:00:10.437 ***********
2026-06-08 12:56:23.073695 | controller | ok: [instance]
2026-06-08 12:56:23.073864 | controller |
2026-06-08 12:56:23.074300 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 12:56:23.074530 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.345)       0:00:10.783 ***********
2026-06-08 12:56:23.130707 | controller | ok: [instance]
2026-06-08 12:56:23.130846 | controller |
2026-06-08 12:56:23.131106 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 12:56:23.131360 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.056)       0:00:10.840 ***********
2026-06-08 12:56:23.160673 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 12:56:23.166047 | controller |
2026-06-08 12:56:23.166171 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-06-08 12:56:23.166360 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.035)       0:00:10.876 ***********
2026-06-08 12:56:23.198810 | controller | ok: [instance] => {
2026-06-08 12:56:23.198983 | controller |     "changed": false,
2026-06-08 12:56:23.199219 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:23.199426 | controller | }
2026-06-08 12:56:23.199598 | controller |
2026-06-08 12:56:23.199801 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-06-08 12:56:23.200071 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.032)       0:00:10.908 ***********
2026-06-08 12:56:23.238370 | 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 12:56:23.238428 | controller |
2026-06-08 12:56:23.238573 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-06-08 12:56:23.238736 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.039)       0:00:10.948 ***********
2026-06-08 12:56:23.579136 | controller | ok: [instance]
2026-06-08 12:56:23.579191 | controller |
2026-06-08 12:56:23.579337 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-06-08 12:56:23.579375 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.340)       0:00:11.289 ***********
2026-06-08 12:56:23.613044 | controller |
2026-06-08 12:56:23.613087 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 12:56:23.613095 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.033)       0:00:11.323 ***********
2026-06-08 12:56:23.637610 | 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 12:56:23.637649 | controller |
2026-06-08 12:56:23.637655 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 12:56:23.637660 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.024)       0:00:11.347 ***********
2026-06-08 12:56:23.992554 | controller | ok: [instance]
2026-06-08 12:56:23.992598 | controller |
2026-06-08 12:56:23.992605 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 12:56:23.992612 | controller | Monday 08 June 2026  12:56:23 +0000 (0:00:00.354)       0:00:11.701 ***********
2026-06-08 12:56:24.028336 | controller | ok: [instance]
2026-06-08 12:56:24.028572 | controller |
2026-06-08 12:56:24.028764 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 12:56:24.029038 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.036)       0:00:11.738 ***********
2026-06-08 12:56:24.069745 | controller | skipping: [instance]
2026-06-08 12:56:24.069911 | controller |
2026-06-08 12:56:24.070079 | controller | TASK [Query mock state] ********************************************************
2026-06-08 12:56:24.070207 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.041)       0:00:11.779 ***********
2026-06-08 12:56:24.425036 | controller | ok: [instance]
2026-06-08 12:56:24.425076 | controller |
2026-06-08 12:56:24.425083 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-06-08 12:56:24.425090 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.354)       0:00:12.134 ***********
2026-06-08 12:56:24.451226 | controller | ok: [instance] => {
2026-06-08 12:56:24.451281 | controller |     "changed": false,
2026-06-08 12:56:24.451288 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:24.451294 | controller | }
2026-06-08 12:56:24.451299 | controller |
2026-06-08 12:56:24.451304 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-06-08 12:56:24.451310 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.026)       0:00:12.160 ***********
2026-06-08 12:56:24.793331 | controller | ok: [instance]
2026-06-08 12:56:24.793373 | controller |
2026-06-08 12:56:24.793380 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-06-08 12:56:24.793386 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.342)       0:00:12.502 ***********
2026-06-08 12:56:24.826149 | controller |
2026-06-08 12:56:24.826356 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 12:56:24.826519 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.033)       0:00:12.536 ***********
2026-06-08 12:56:24.856236 | 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 12:56:24.856489 | controller |
2026-06-08 12:56:24.856621 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 12:56:24.856747 | controller | Monday 08 June 2026  12:56:24 +0000 (0:00:00.029)       0:00:12.566 ***********
2026-06-08 12:56:25.202310 | controller | ok: [instance]
2026-06-08 12:56:25.202477 | controller |
2026-06-08 12:56:25.202613 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 12:56:25.202746 | controller | Monday 08 June 2026  12:56:25 +0000 (0:00:00.346)       0:00:12.912 ***********
2026-06-08 12:56:25.237246 | controller | ok: [instance]
2026-06-08 12:56:25.237406 | controller |
2026-06-08 12:56:25.237535 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 12:56:25.237674 | controller | Monday 08 June 2026  12:56:25 +0000 (0:00:00.034)       0:00:12.947 ***********
2026-06-08 12:56:25.270665 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 12:56:25.278762 | controller |
2026-06-08 12:56:25.279126 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 12:56:25.279386 | controller | Monday 08 June 2026  12:56:25 +0000 (0:00:00.041)       0:00:12.989 ***********
2026-06-08 12:56:25.322204 | controller | skipping: [instance]
2026-06-08 12:56:25.322369 | controller |
2026-06-08 12:56:25.322512 | controller | TASK [bm_sno : Set GenericUsbBoot BIOS attribute] ******************************
2026-06-08 12:56:25.322644 | controller | Monday 08 June 2026  12:56:25 +0000 (0:00:00.042)       0:00:13.032 ***********
2026-06-08 12:56:25.672336 | controller | ok: [instance]
2026-06-08 12:56:25.672534 | controller |
2026-06-08 12:56:25.672702 | controller | TASK [bm_sno : Create BIOS config job to schedule the change] ******************
2026-06-08 12:56:25.672873 | controller | Monday 08 June 2026  12:56:25 +0000 (0:00:00.350)       0:00:13.382 ***********
2026-06-08 12:56:26.042719 | controller | ok: [instance]
2026-06-08 12:56:26.042898 | controller |
2026-06-08 12:56:26.043070 | controller | TASK [bm_sno : Power off before applying BIOS change] **************************
2026-06-08 12:56:26.043219 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.369)       0:00:13.752 ***********
2026-06-08 12:56:26.084286 | 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 12:56:26.084444 | controller |
2026-06-08 12:56:26.084583 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:26.084742 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.041)       0:00:13.794 ***********
2026-06-08 12:56:26.447590 | controller | ok: [instance]
2026-06-08 12:56:26.447758 | controller |
2026-06-08 12:56:26.447906 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 12:56:26.448052 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.363)       0:00:14.157 ***********
2026-06-08 12:56:26.468506 | controller | skipping: [instance]
2026-06-08 12:56:26.468710 | controller |
2026-06-08 12:56:26.468897 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 12:56:26.469125 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.021)       0:00:14.178 ***********
2026-06-08 12:56:26.488682 | controller | skipping: [instance]
2026-06-08 12:56:26.488834 | controller |
2026-06-08 12:56:26.489000 | controller | TASK [bm_sno : Power on to apply BIOS config job during POST] ******************
2026-06-08 12:56:26.489130 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.020)       0:00:14.199 ***********
2026-06-08 12:56:26.515274 | 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 12:56:26.515447 | controller |
2026-06-08 12:56:26.515645 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:26.515818 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.026)       0:00:14.225 ***********
2026-06-08 12:56:26.862840 | controller | ok: [instance]
2026-06-08 12:56:26.863039 | controller |
2026-06-08 12:56:26.863270 | controller | TASK [bm_sno : Power on bare metal host] ***************************************
2026-06-08 12:56:26.863410 | controller | Monday 08 June 2026  12:56:26 +0000 (0:00:00.346)       0:00:14.572 ***********
2026-06-08 12:56:27.221806 | controller | ok: [instance]
2026-06-08 12:56:27.222085 | controller |
2026-06-08 12:56:27.222315 | controller | TASK [bm_sno : Wait for host POST to complete] *********************************
2026-06-08 12:56:27.222508 | controller | Monday 08 June 2026  12:56:27 +0000 (0:00:00.359)       0:00:14.931 ***********
2026-06-08 12:56:27.605630 | controller | ok: [instance]
2026-06-08 12:56:27.605979 | controller |
2026-06-08 12:56:27.606279 | controller | TASK [bm_sno : Show POST state] ************************************************
2026-06-08 12:56:27.606552 | controller | Monday 08 June 2026  12:56:27 +0000 (0:00:00.383)       0:00:15.315 ***********
2026-06-08 12:56:27.645215 | controller | ok: [instance] => {
2026-06-08 12:56:27.645497 | controller |     "msg": "POST state: FinishedPost"
2026-06-08 12:56:27.645698 | controller | }
2026-06-08 12:56:27.645870 | controller |
2026-06-08 12:56:27.646086 | controller | TASK [bm_sno : Power off after BIOS change applied] ****************************
2026-06-08 12:56:27.646274 | controller | Monday 08 June 2026  12:56:27 +0000 (0:00:00.039)       0:00:15.355 ***********
2026-06-08 12:56:27.682946 | 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 12:56:27.683308 | controller |
2026-06-08 12:56:27.683608 | controller | TASK [bm_sno : Query current power state] **************************************
2026-06-08 12:56:27.683900 | controller | Monday 08 June 2026  12:56:27 +0000 (0:00:00.038)       0:00:15.393 ***********
2026-06-08 12:56:28.044208 | controller | ok: [instance]
2026-06-08 12:56:28.044375 | controller |
2026-06-08 12:56:28.044557 | controller | TASK [bm_sno : Force power off via Redfish] ************************************
2026-06-08 12:56:28.044694 | controller | Monday 08 June 2026  12:56:28 +0000 (0:00:00.360)       0:00:15.754 ***********
2026-06-08 12:56:28.438854 | controller | ok: [instance]
2026-06-08 12:56:28.439059 | controller |
2026-06-08 12:56:28.439222 | controller | TASK [bm_sno : Wait for host to power off] *************************************
2026-06-08 12:56:28.439360 | controller | Monday 08 June 2026  12:56:28 +0000 (0:00:00.394)       0:00:16.148 ***********
2026-06-08 12:56:28.812990 | controller | ok: [instance]
2026-06-08 12:56:28.813167 | controller |
2026-06-08 12:56:28.813305 | controller | TASK [Query mock state after auto-enable] **************************************
2026-06-08 12:56:28.813435 | controller | Monday 08 June 2026  12:56:28 +0000 (0:00:00.374)       0:00:16.523 ***********
2026-06-08 12:56:29.183366 | controller | ok: [instance]
2026-06-08 12:56:29.183591 | controller |
2026-06-08 12:56:29.183786 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-06-08 12:56:29.184028 | controller | Monday 08 June 2026  12:56:29 +0000 (0:00:00.370)       0:00:16.893 ***********
2026-06-08 12:56:29.216590 | controller | ok: [instance] => {
2026-06-08 12:56:29.216857 | controller |     "changed": false,
2026-06-08 12:56:29.217170 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:29.217379 | controller | }
2026-06-08 12:56:29.217592 | controller |
2026-06-08 12:56:29.217782 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-06-08 12:56:29.218060 | controller | Monday 08 June 2026  12:56:29 +0000 (0:00:00.032)       0:00:16.926 ***********
2026-06-08 12:56:29.595073 | controller | ok: [instance]
2026-06-08 12:56:29.595754 | controller |
2026-06-08 12:56:29.595798 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-06-08 12:56:29.595809 | controller | Monday 08 June 2026  12:56:29 +0000 (0:00:00.378)       0:00:17.305 ***********
2026-06-08 12:56:29.633574 | controller |
2026-06-08 12:56:29.634284 | controller | TASK [bm_sno : Check current GenericUsbBoot state] *****************************
2026-06-08 12:56:29.634312 | controller | Monday 08 June 2026  12:56:29 +0000 (0:00:00.037)       0:00:17.343 ***********
2026-06-08 12:56:29.659371 | 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 12:56:29.659398 | controller |
2026-06-08 12:56:29.659402 | controller | TASK [bm_sno : Read GenericUsbBoot BIOS attribute] *****************************
2026-06-08 12:56:29.659407 | controller | Monday 08 June 2026  12:56:29 +0000 (0:00:00.026)       0:00:17.369 ***********
2026-06-08 12:56:30.024276 | controller | ok: [instance]
2026-06-08 12:56:30.024442 | controller |
2026-06-08 12:56:30.024599 | controller | TASK [bm_sno : Set GenericUsbBoot status fact] *********************************
2026-06-08 12:56:30.024737 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.364)       0:00:17.733 ***********
2026-06-08 12:56:30.065872 | controller | ok: [instance]
2026-06-08 12:56:30.066108 | controller |
2026-06-08 12:56:30.066315 | controller | TASK [bm_sno : Fail if GenericUsbBoot is disabled] *****************************
2026-06-08 12:56:30.066540 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.041)       0:00:17.775 ***********
2026-06-08 12:56:30.098112 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-06-08 12:56:30.106670 | controller |
2026-06-08 12:56:30.106876 | controller | TASK [bm_sno : Fail if auto-enable is off] *************************************
2026-06-08 12:56:30.107079 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.041)       0:00:17.816 ***********
2026-06-08 12:56:30.161304 | 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 12:56:30.166519 | controller |
2026-06-08 12:56:30.166705 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-06-08 12:56:30.166841 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.060)       0:00:17.877 ***********
2026-06-08 12:56:30.195001 | controller | ok: [instance] => {
2026-06-08 12:56:30.195163 | controller |     "changed": false,
2026-06-08 12:56:30.195297 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:30.195419 | controller | }
2026-06-08 12:56:30.195535 | controller |
2026-06-08 12:56:30.195666 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-06-08 12:56:30.195793 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.028)       0:00:17.905 ***********
2026-06-08 12:56:30.237015 | 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 12:56:30.237702 | controller |
2026-06-08 12:56:30.237883 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 12:56:30.238036 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.041)       0:00:17.947 ***********
2026-06-08 12:56:30.635966 | controller | ok: [instance]
2026-06-08 12:56:30.636000 | controller |
2026-06-08 12:56:30.636005 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-06-08 12:56:30.636010 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.398)       0:00:18.345 ***********
2026-06-08 12:56:30.665193 | controller |
2026-06-08 12:56:30.665257 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 12:56:30.665269 | controller | Monday 08 June 2026  12:56:30 +0000 (0:00:00.029)       0:00:18.375 ***********
2026-06-08 12:56:31.006185 | controller | ok: [instance]
2026-06-08 12:56:31.006802 | controller |
2026-06-08 12:56:31.006848 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 12:56:31.006858 | controller | Monday 08 June 2026  12:56:31 +0000 (0:00:00.340)       0:00:18.715 ***********
2026-06-08 12:56:36.036937 | controller | Pausing for 5 seconds
2026-06-08 12:56:36.037013 | controller | ok: [instance]
2026-06-08 12:56:36.037024 | controller |
2026-06-08 12:56:36.037033 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 12:56:36.037041 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:05.030)       0:00:23.745 ***********
2026-06-08 12:56:36.355619 | controller | ok: [instance]
2026-06-08 12:56:36.355657 | controller |
2026-06-08 12:56:36.355664 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 12:56:36.355671 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.319)       0:00:24.065 ***********
2026-06-08 12:56:36.404180 | controller | ok: [instance] => {
2026-06-08 12:56:36.404231 | controller |     "msg": ""
2026-06-08 12:56:36.404242 | controller | }
2026-06-08 12:56:36.404251 | controller |
2026-06-08 12:56:36.404260 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 12:56:36.404276 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.047)       0:00:24.113 ***********
2026-06-08 12:56:36.441072 | controller | skipping: [instance]
2026-06-08 12:56:36.441114 | controller |
2026-06-08 12:56:36.441122 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 12:56:36.441128 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.037)       0:00:24.150 ***********
2026-06-08 12:56:36.481203 | controller | skipping: [instance]
2026-06-08 12:56:36.481523 | controller |
2026-06-08 12:56:36.481821 | controller | TASK [Query mock state after eject] ********************************************
2026-06-08 12:56:36.482147 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.040)       0:00:24.190 ***********
2026-06-08 12:56:36.867985 | controller | ok: [instance]
2026-06-08 12:56:36.868038 | controller |
2026-06-08 12:56:36.868052 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-06-08 12:56:36.868064 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.386)       0:00:24.577 ***********
2026-06-08 12:56:36.904144 | controller | ok: [instance] => {
2026-06-08 12:56:36.904183 | controller |     "changed": false,
2026-06-08 12:56:36.905500 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:36.905558 | controller | }
2026-06-08 12:56:36.905572 | controller |
2026-06-08 12:56:36.905584 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-06-08 12:56:36.905595 | controller | Monday 08 June 2026  12:56:36 +0000 (0:00:00.036)       0:00:24.613 ***********
2026-06-08 12:56:37.248163 | controller | ok: [instance]
2026-06-08 12:56:37.248211 | controller |
2026-06-08 12:56:37.248369 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-06-08 12:56:37.248405 | controller | Monday 08 June 2026  12:56:37 +0000 (0:00:00.344)       0:00:24.958 ***********
2026-06-08 12:56:37.278657 | controller |
2026-06-08 12:56:37.278691 | controller | TASK [bm_sno : Eject VirtualMedia] *********************************************
2026-06-08 12:56:37.278696 | controller | Monday 08 June 2026  12:56:37 +0000 (0:00:00.030)       0:00:24.988 ***********
2026-06-08 12:56:37.644751 | controller | ok: [instance]
2026-06-08 12:56:37.644802 | controller |
2026-06-08 12:56:37.644815 | controller | TASK [bm_sno : Wait for VirtualMedia eject to settle] **************************
2026-06-08 12:56:37.644837 | controller | Monday 08 June 2026  12:56:37 +0000 (0:00:00.364)       0:00:25.353 ***********
2026-06-08 12:56:42.679176 | controller | Pausing for 5 seconds
2026-06-08 12:56:42.679264 | controller | ok: [instance]
2026-06-08 12:56:42.679596 | controller |
2026-06-08 12:56:42.679642 | controller | TASK [bm_sno : Check Remote File Share status] *********************************
2026-06-08 12:56:42.679648 | controller | Monday 08 June 2026  12:56:42 +0000 (0:00:05.034)       0:00:30.388 ***********
2026-06-08 12:56:42.906670 | controller | ok: [instance]
2026-06-08 12:56:42.906701 | controller |
2026-06-08 12:56:42.906706 | controller | TASK [bm_sno : Show Remote File Share status before reset] *********************
2026-06-08 12:56:42.906711 | controller | Monday 08 June 2026  12:56:42 +0000 (0:00:00.227)       0:00:30.616 ***********
2026-06-08 12:56:42.941135 | controller | ok: [instance] => {
2026-06-08 12:56:42.941177 | controller |     "msg": ""
2026-06-08 12:56:42.941185 | controller | }
2026-06-08 12:56:42.941192 | controller |
2026-06-08 12:56:42.941197 | controller | TASK [bm_sno : Run racadm racreset] ********************************************
2026-06-08 12:56:42.941207 | controller | Monday 08 June 2026  12:56:42 +0000 (0:00:00.034)       0:00:30.651 ***********
2026-06-08 12:56:42.972927 | controller | skipping: [instance]
2026-06-08 12:56:42.972975 | controller |
2026-06-08 12:56:42.972982 | controller | TASK [bm_sno : Wait for iDRAC SSH to come back up] *****************************
2026-06-08 12:56:42.972986 | controller | Monday 08 June 2026  12:56:42 +0000 (0:00:00.031)       0:00:30.682 ***********
2026-06-08 12:56:43.009105 | controller | skipping: [instance]
2026-06-08 12:56:43.009362 | controller |
2026-06-08 12:56:43.009376 | controller | TASK [Query mock state] ********************************************************
2026-06-08 12:56:43.009382 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.036)       0:00:30.719 ***********
2026-06-08 12:56:43.362579 | controller | ok: [instance]
2026-06-08 12:56:43.362620 | controller |
2026-06-08 12:56:43.362626 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-06-08 12:56:43.362632 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.352)       0:00:31.072 ***********
2026-06-08 12:56:43.414264 | controller | ok: [instance] => {
2026-06-08 12:56:43.414326 | controller |     "changed": false,
2026-06-08 12:56:43.414332 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:43.414338 | controller | }
2026-06-08 12:56:43.414344 | controller |
2026-06-08 12:56:43.414350 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-06-08 12:56:43.414356 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.051)       0:00:31.123 ***********
2026-06-08 12:56:43.501941 | 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 12:56:43.502004 | controller |
2026-06-08 12:56:43.502013 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 12:56:43.502019 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.087)       0:00:31.211 ***********
2026-06-08 12:56:43.526614 | controller | ok: [instance]
2026-06-08 12:56:43.526838 | controller |
2026-06-08 12:56:43.527037 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 12:56:43.527202 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.025)       0:00:31.236 ***********
2026-06-08 12:56:43.896236 | controller | ok: [instance]
2026-06-08 12:56:43.896294 | controller |
2026-06-08 12:56:43.896305 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-06-08 12:56:43.896321 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.369)       0:00:31.606 ***********
2026-06-08 12:56:43.940879 | controller |
2026-06-08 12:56:43.940938 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 12:56:43.940970 | controller | Monday 08 June 2026  12:56:43 +0000 (0:00:00.044)       0:00:31.650 ***********
2026-06-08 12:56:44.324227 | controller | ok: [instance]
2026-06-08 12:56:44.324295 | controller |
2026-06-08 12:56:44.324306 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 12:56:44.324313 | controller | Monday 08 June 2026  12:56:44 +0000 (0:00:00.383)       0:00:32.034 ***********
2026-06-08 12:56:46.143261 | controller | ok: [instance] => (item=None)
2026-06-08 12:56:46.143317 | controller | ok: [instance] => (item=None)
2026-06-08 12:56:46.143323 | controller | ok: [instance] => (item=None)
2026-06-08 12:56:46.143328 | controller | ok: [instance] => (item=None)
2026-06-08 12:56:46.143333 | controller | ok: [instance] => (item=None)
2026-06-08 12:56:46.143339 | controller | ok: [instance]
2026-06-08 12:56:46.143345 | controller |
2026-06-08 12:56:46.143351 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 12:56:46.143357 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:01.817)       0:00:33.851 ***********
2026-06-08 12:56:46.203134 | controller | ok: [instance]
2026-06-08 12:56:46.203175 | controller |
2026-06-08 12:56:46.203441 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 12:56:46.203489 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.061)       0:00:33.912 ***********
2026-06-08 12:56:46.249420 | controller | ok: [instance] => {
2026-06-08 12:56:46.249483 | controller |     "msg": [
2026-06-08 12:56:46.249490 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 12:56:46.250900 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 12:56:46.250971 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 12:56:46.250983 | 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 12:56:46.250991 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:56:46.250998 | controller |     ]
2026-06-08 12:56:46.251004 | controller | }
2026-06-08 12:56:46.251010 | controller |
2026-06-08 12:56:46.251017 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 12:56:46.251023 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.046)       0:00:33.958 ***********
2026-06-08 12:56:46.282230 | controller | skipping: [instance]
2026-06-08 12:56:46.282467 | controller |
2026-06-08 12:56:46.282737 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 12:56:46.282924 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.033)       0:00:33.992 ***********
2026-06-08 12:56:46.377598 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:56:46.377840 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:56:46.378051 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:56:46.378261 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:56:46.378446 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:56:46.378618 | controller |
2026-06-08 12:56:46.378799 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 12:56:46.378996 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.095)       0:00:34.087 ***********
2026-06-08 12:56:46.479066 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:56:46.479313 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:56:46.479475 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:56:46.479654 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:56:46.479826 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:56:46.480023 | controller | skipping: [instance]
2026-06-08 12:56:46.480175 | controller |
2026-06-08 12:56:46.480330 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 12:56:46.480481 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.100)       0:00:34.188 ***********
2026-06-08 12:56:46.564276 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:56:46.564498 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:56:46.564693 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:56:46.564859 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:56:46.565064 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:56:46.565232 | controller | skipping: [instance]
2026-06-08 12:56:46.565386 | controller |
2026-06-08 12:56:46.565552 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 12:56:46.565725 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.085)       0:00:34.274 ***********
2026-06-08 12:56:46.605027 | controller | skipping: [instance]
2026-06-08 12:56:46.605259 | controller |
2026-06-08 12:56:46.605417 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 12:56:46.605578 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.040)       0:00:34.314 ***********
2026-06-08 12:56:46.631433 | controller | ok: [instance] => {
2026-06-08 12:56:46.631686 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:56:46.631861 | controller | }
2026-06-08 12:56:46.632050 | controller |
2026-06-08 12:56:46.632254 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 12:56:46.632430 | controller | Monday 08 June 2026  12:56:46 +0000 (0:00:00.026)       0:00:34.341 ***********
2026-06-08 12:56:47.010402 | controller | ok: [instance]
2026-06-08 12:56:47.010471 | controller |
2026-06-08 12:56:47.010477 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 12:56:47.010482 | controller | Monday 08 June 2026  12:56:47 +0000 (0:00:00.378)       0:00:34.720 ***********
2026-06-08 12:56:57.050234 | controller | Pausing for 10 seconds
2026-06-08 12:56:57.051007 | controller | ok: [instance]
2026-06-08 12:56:57.051090 | controller |
2026-06-08 12:56:57.051106 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 12:56:57.051120 | controller | Monday 08 June 2026  12:56:57 +0000 (0:00:10.038)       0:00:44.759 ***********
2026-06-08 12:56:57.400183 | controller | ok: [instance]
2026-06-08 12:56:57.400249 | controller |
2026-06-08 12:56:57.400258 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 12:56:57.400459 | controller | Monday 08 June 2026  12:56:57 +0000 (0:00:00.350)       0:00:45.109 ***********
2026-06-08 12:56:57.758847 | controller | ok: [instance]
2026-06-08 12:56:57.759062 | controller |
2026-06-08 12:56:57.759200 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 12:56:57.759328 | controller | Monday 08 June 2026  12:56:57 +0000 (0:00:00.359)       0:00:45.469 ***********
2026-06-08 12:56:57.800573 | controller | ok: [instance] => {
2026-06-08 12:56:57.800751 | controller |     "changed": false,
2026-06-08 12:56:57.800887 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:57.801036 | controller | }
2026-06-08 12:56:57.801157 | controller |
2026-06-08 12:56:57.801282 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 12:56:57.801431 | controller | Monday 08 June 2026  12:56:57 +0000 (0:00:00.041)       0:00:45.510 ***********
2026-06-08 12:56:57.829750 | controller | ok: [instance] => {
2026-06-08 12:56:57.830007 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:56:57.830163 | controller | }
2026-06-08 12:56:57.830292 | controller |
2026-06-08 12:56:57.830419 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 12:56:57.830543 | controller | Monday 08 June 2026  12:56:57 +0000 (0:00:00.029)       0:00:45.540 ***********
2026-06-08 12:56:58.210109 | controller | ok: [instance]
2026-06-08 12:56:58.210186 | controller |
2026-06-08 12:56:58.210191 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 12:56:58.210196 | controller | Monday 08 June 2026  12:56:58 +0000 (0:00:00.379)       0:00:45.919 ***********
2026-06-08 12:56:58.252168 | controller | ok: [instance] => {
2026-06-08 12:56:58.252220 | controller |     "changed": false,
2026-06-08 12:56:58.252230 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:58.252239 | controller | }
2026-06-08 12:56:58.252377 | controller |
2026-06-08 12:56:58.252407 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-06-08 12:56:58.252412 | controller | Monday 08 June 2026  12:56:58 +0000 (0:00:00.042)       0:00:45.962 ***********
2026-06-08 12:56:58.317740 | controller | ok: [instance] => {
2026-06-08 12:56:58.317778 | controller |     "changed": false,
2026-06-08 12:56:58.317783 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:58.317787 | controller | }
2026-06-08 12:56:58.317792 | controller |
2026-06-08 12:56:58.317796 | controller | TASK [Query mock state after discover] *****************************************
2026-06-08 12:56:58.317801 | controller | Monday 08 June 2026  12:56:58 +0000 (0:00:00.065)       0:00:46.027 ***********
2026-06-08 12:56:58.664465 | controller | ok: [instance]
2026-06-08 12:56:58.664509 | controller |
2026-06-08 12:56:58.664516 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 12:56:58.664522 | controller | Monday 08 June 2026  12:56:58 +0000 (0:00:00.346)       0:00:46.374 ***********
2026-06-08 12:56:58.701169 | controller | ok: [instance] => {
2026-06-08 12:56:58.701235 | controller |     "changed": false,
2026-06-08 12:56:58.701241 | controller |     "msg": "All assertions passed"
2026-06-08 12:56:58.701592 | controller | }
2026-06-08 12:56:58.701641 | controller |
2026-06-08 12:56:58.701648 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 12:56:58.701655 | controller | Monday 08 June 2026  12:56:58 +0000 (0:00:00.036)       0:00:46.411 ***********
2026-06-08 12:56:59.063599 | controller | ok: [instance]
2026-06-08 12:56:59.063642 | controller |
2026-06-08 12:56:59.063648 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-06-08 12:56:59.063653 | controller | Monday 08 June 2026  12:56:59 +0000 (0:00:00.362)       0:00:46.773 ***********
2026-06-08 12:56:59.101231 | controller |
2026-06-08 12:56:59.101304 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 12:56:59.101420 | controller | Monday 08 June 2026  12:56:59 +0000 (0:00:00.037)       0:00:46.810 ***********
2026-06-08 12:56:59.448923 | controller | ok: [instance]
2026-06-08 12:56:59.448973 | controller |
2026-06-08 12:56:59.448979 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 12:56:59.448983 | controller | Monday 08 June 2026  12:56:59 +0000 (0:00:00.348)       0:00:47.159 ***********
2026-06-08 12:57:01.165217 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:01.165291 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:01.165298 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:01.166147 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:01.166201 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:01.166208 | controller | ok: [instance]
2026-06-08 12:57:01.166215 | controller |
2026-06-08 12:57:01.166221 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 12:57:01.166229 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:01.715)       0:00:48.874 ***********
2026-06-08 12:57:01.205217 | controller | ok: [instance]
2026-06-08 12:57:01.205599 | controller |
2026-06-08 12:57:01.205648 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 12:57:01.205658 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.040)       0:00:48.915 ***********
2026-06-08 12:57:01.248205 | controller | ok: [instance] => {
2026-06-08 12:57:01.248262 | controller |     "msg": [
2026-06-08 12:57:01.248274 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 12:57:01.248284 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 12:57:01.249786 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 12:57:01.249803 | 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 12:57:01.249811 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:01.249817 | controller |     ]
2026-06-08 12:57:01.249822 | controller | }
2026-06-08 12:57:01.249828 | controller |
2026-06-08 12:57:01.249833 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 12:57:01.249839 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.042)       0:00:48.957 ***********
2026-06-08 12:57:01.314850 | controller | ok: [instance] => {
2026-06-08 12:57:01.315161 | controller |     "changed": false,
2026-06-08 12:57:01.315359 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:01.315529 | controller | }
2026-06-08 12:57:01.315689 | controller |
2026-06-08 12:57:01.315859 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 12:57:01.316081 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.066)       0:00:49.024 ***********
2026-06-08 12:57:01.385234 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:01.385458 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:01.385630 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:57:01.385809 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:01.386100 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:01.386282 | controller | skipping: [instance]
2026-06-08 12:57:01.386441 | controller |
2026-06-08 12:57:01.386609 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 12:57:01.386744 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.070)       0:00:49.095 ***********
2026-06-08 12:57:01.483473 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:01.483783 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:01.484082 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:57:01.484347 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:01.484610 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:01.484864 | controller | skipping: [instance]
2026-06-08 12:57:01.485138 | controller |
2026-06-08 12:57:01.485403 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 12:57:01.485656 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.098)       0:00:49.193 ***********
2026-06-08 12:57:01.572860 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:01.573215 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:01.573506 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-06-08 12:57:01.573770 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:01.574068 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:01.574401 | controller | skipping: [instance]
2026-06-08 12:57:01.574645 | controller |
2026-06-08 12:57:01.574902 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 12:57:01.575195 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.089)       0:00:49.283 ***********
2026-06-08 12:57:01.624401 | controller | skipping: [instance]
2026-06-08 12:57:01.624557 | controller |
2026-06-08 12:57:01.624681 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 12:57:01.624808 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.051)       0:00:49.334 ***********
2026-06-08 12:57:01.653857 | controller | ok: [instance] => {
2026-06-08 12:57:01.654343 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:57:01.654667 | controller | }
2026-06-08 12:57:01.655061 | controller |
2026-06-08 12:57:01.655415 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 12:57:01.655687 | controller | Monday 08 June 2026  12:57:01 +0000 (0:00:00.028)       0:00:49.363 ***********
2026-06-08 12:57:02.031087 | controller | ok: [instance]
2026-06-08 12:57:02.031301 | controller |
2026-06-08 12:57:02.031477 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 12:57:02.031654 | controller | Monday 08 June 2026  12:57:02 +0000 (0:00:00.377)       0:00:49.741 ***********
2026-06-08 12:57:12.070127 | controller | Pausing for 10 seconds
2026-06-08 12:57:12.070316 | controller | ok: [instance]
2026-06-08 12:57:12.070508 | controller |
2026-06-08 12:57:12.070736 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 12:57:12.070973 | controller | Monday 08 June 2026  12:57:12 +0000 (0:00:10.038)       0:00:59.780 ***********
2026-06-08 12:57:12.463523 | controller | ok: [instance]
2026-06-08 12:57:12.463560 | controller |
2026-06-08 12:57:12.463565 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 12:57:12.463570 | controller | Monday 08 June 2026  12:57:12 +0000 (0:00:00.393)       0:01:00.173 ***********
2026-06-08 12:57:12.819139 | controller | ok: [instance]
2026-06-08 12:57:12.819186 | controller |
2026-06-08 12:57:12.819193 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 12:57:12.819203 | controller | Monday 08 June 2026  12:57:12 +0000 (0:00:00.355)       0:01:00.528 ***********
2026-06-08 12:57:12.865253 | controller | ok: [instance] => {
2026-06-08 12:57:12.865310 | controller |     "changed": false,
2026-06-08 12:57:12.865315 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:12.865320 | controller | }
2026-06-08 12:57:12.865515 | controller |
2026-06-08 12:57:12.865555 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 12:57:12.865561 | controller | Monday 08 June 2026  12:57:12 +0000 (0:00:00.045)       0:01:00.574 ***********
2026-06-08 12:57:12.900857 | controller | ok: [instance] => {
2026-06-08 12:57:12.900907 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:57:12.900915 | controller | }
2026-06-08 12:57:12.900921 | controller |
2026-06-08 12:57:12.900927 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 12:57:12.900934 | controller | Monday 08 June 2026  12:57:12 +0000 (0:00:00.035)       0:01:00.609 ***********
2026-06-08 12:57:13.261168 | controller | ok: [instance]
2026-06-08 12:57:13.261236 | controller |
2026-06-08 12:57:13.261318 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 12:57:13.261331 | controller | Monday 08 June 2026  12:57:13 +0000 (0:00:00.360)       0:01:00.970 ***********
2026-06-08 12:57:13.323221 | controller | ok: [instance] => {
2026-06-08 12:57:13.323276 | controller |     "changed": false,
2026-06-08 12:57:13.323281 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:13.323285 | controller | }
2026-06-08 12:57:13.323289 | controller |
2026-06-08 12:57:13.323293 | controller | TASK [Query mock state] ********************************************************
2026-06-08 12:57:13.323321 | controller | Monday 08 June 2026  12:57:13 +0000 (0:00:00.062)       0:01:01.033 ***********
2026-06-08 12:57:13.684225 | controller | ok: [instance]
2026-06-08 12:57:13.684281 | controller |
2026-06-08 12:57:13.684291 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-06-08 12:57:13.684305 | controller | Monday 08 June 2026  12:57:13 +0000 (0:00:00.361)       0:01:01.394 ***********
2026-06-08 12:57:13.712241 | controller | ok: [instance] => {
2026-06-08 12:57:13.712299 | controller |     "changed": false,
2026-06-08 12:57:13.712306 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:13.712311 | controller | }
2026-06-08 12:57:13.712333 | controller |
2026-06-08 12:57:13.712337 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 12:57:13.712484 | controller | Monday 08 June 2026  12:57:13 +0000 (0:00:00.027)       0:01:01.421 ***********
2026-06-08 12:57:13.733199 | controller | ok: [instance]
2026-06-08 12:57:13.733246 | controller |
2026-06-08 12:57:13.733253 | controller | TASK [Reset mock without Virtual Optical Drive] ********************************
2026-06-08 12:57:13.733260 | controller | Monday 08 June 2026  12:57:13 +0000 (0:00:00.020)       0:01:01.442 ***********
2026-06-08 12:57:14.072730 | controller | ok: [instance]
2026-06-08 12:57:14.072799 | controller |
2026-06-08 12:57:14.072805 | controller | TASK [Include bm_discover_vmedia_target (floppy fallback)] *********************
2026-06-08 12:57:14.072811 | controller | Monday 08 June 2026  12:57:14 +0000 (0:00:00.339)       0:01:01.782 ***********
2026-06-08 12:57:14.120427 | controller |
2026-06-08 12:57:14.120473 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 12:57:14.120479 | controller | Monday 08 June 2026  12:57:14 +0000 (0:00:00.047)       0:01:01.830 ***********
2026-06-08 12:57:14.489483 | controller | ok: [instance]
2026-06-08 12:57:14.489525 | controller |
2026-06-08 12:57:14.489538 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 12:57:14.489544 | controller | Monday 08 June 2026  12:57:14 +0000 (0:00:00.368)       0:01:02.198 ***********
2026-06-08 12:57:16.020397 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:16.020459 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:16.020466 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:16.020471 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:16.021131 | controller | ok: [instance]
2026-06-08 12:57:16.021189 | controller |
2026-06-08 12:57:16.021203 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 12:57:16.021223 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:01.530)       0:01:03.729 ***********
2026-06-08 12:57:16.091840 | controller | ok: [instance]
2026-06-08 12:57:16.091887 | controller |
2026-06-08 12:57:16.091894 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 12:57:16.091901 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.071)       0:01:03.800 ***********
2026-06-08 12:57:16.148104 | controller | ok: [instance] => {
2026-06-08 12:57:16.148361 | controller |     "msg": [
2026-06-08 12:57:16.148933 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 12:57:16.149182 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 12:57:16.149462 | 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 12:57:16.149720 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:16.150135 | controller |     ]
2026-06-08 12:57:16.150379 | controller | }
2026-06-08 12:57:16.150606 | controller |
2026-06-08 12:57:16.150884 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 12:57:16.151176 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.057)       0:01:03.857 ***********
2026-06-08 12:57:16.189535 | controller | skipping: [instance]
2026-06-08 12:57:16.189638 | controller |
2026-06-08 12:57:16.189745 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 12:57:16.189869 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.041)       0:01:03.899 ***********
2026-06-08 12:57:16.276089 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:16.276150 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:16.276167 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:16.276188 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:16.276262 | controller | skipping: [instance]
2026-06-08 12:57:16.276503 | controller |
2026-06-08 12:57:16.276670 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 12:57:16.276853 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.085)       0:01:03.985 ***********
2026-06-08 12:57:16.348821 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:16.349374 | controller | ok: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:16.349382 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:16.349397 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:16.349402 | controller |
2026-06-08 12:57:16.349407 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 12:57:16.349412 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.070)       0:01:04.056 ***********
2026-06-08 12:57:16.420229 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:16.420289 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-06-08 12:57:16.420992 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:16.421044 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:16.421052 | controller | skipping: [instance]
2026-06-08 12:57:16.421059 | controller |
2026-06-08 12:57:16.421064 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 12:57:16.421071 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.073)       0:01:04.130 ***********
2026-06-08 12:57:16.475753 | controller | skipping: [instance]
2026-06-08 12:57:16.475784 | controller |
2026-06-08 12:57:16.475789 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 12:57:16.475794 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.055)       0:01:04.185 ***********
2026-06-08 12:57:16.503923 | controller | ok: [instance] => {
2026-06-08 12:57:16.503970 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:57:16.503976 | controller | }
2026-06-08 12:57:16.503980 | controller |
2026-06-08 12:57:16.503984 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 12:57:16.503989 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.027)       0:01:04.213 ***********
2026-06-08 12:57:16.910114 | controller | ok: [instance]
2026-06-08 12:57:16.910164 | controller |
2026-06-08 12:57:16.910174 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 12:57:16.910188 | controller | Monday 08 June 2026  12:57:16 +0000 (0:00:00.406)       0:01:04.619 ***********
2026-06-08 12:57:26.958297 | controller | Pausing for 10 seconds
2026-06-08 12:57:26.958365 | controller | ok: [instance]
2026-06-08 12:57:26.958377 | controller |
2026-06-08 12:57:26.958509 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 12:57:26.958550 | controller | Monday 08 June 2026  12:57:26 +0000 (0:00:10.048)       0:01:14.668 ***********
2026-06-08 12:57:27.356636 | controller | ok: [instance]
2026-06-08 12:57:27.356674 | controller |
2026-06-08 12:57:27.356680 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 12:57:27.356684 | controller | Monday 08 June 2026  12:57:27 +0000 (0:00:00.398)       0:01:15.066 ***********
2026-06-08 12:57:27.755112 | controller | ok: [instance]
2026-06-08 12:57:27.755147 | controller |
2026-06-08 12:57:27.755329 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 12:57:27.755343 | controller | Monday 08 June 2026  12:57:27 +0000 (0:00:00.398)       0:01:15.465 ***********
2026-06-08 12:57:27.797161 | controller | ok: [instance] => {
2026-06-08 12:57:27.797201 | controller |     "changed": false,
2026-06-08 12:57:27.797207 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:27.797224 | controller | }
2026-06-08 12:57:27.797229 | controller |
2026-06-08 12:57:27.797234 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 12:57:27.797240 | controller | Monday 08 June 2026  12:57:27 +0000 (0:00:00.041)       0:01:15.506 ***********
2026-06-08 12:57:27.819167 | controller | ok: [instance] => {
2026-06-08 12:57:27.819211 | controller |     "msg": "Resolved boot path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-06-08 12:57:27.819218 | controller | }
2026-06-08 12:57:27.819223 | controller |
2026-06-08 12:57:27.819451 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 12:57:27.819466 | controller | Monday 08 June 2026  12:57:27 +0000 (0:00:00.021)       0:01:15.528 ***********
2026-06-08 12:57:28.207468 | controller | ok: [instance]
2026-06-08 12:57:28.207501 | controller |
2026-06-08 12:57:28.207506 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 12:57:28.207511 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.388)       0:01:15.917 ***********
2026-06-08 12:57:28.276211 | controller | ok: [instance] => {
2026-06-08 12:57:28.277290 | controller |     "changed": false,
2026-06-08 12:57:28.277341 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:28.277349 | controller | }
2026-06-08 12:57:28.278250 | controller |
2026-06-08 12:57:28.278321 | controller | TASK [Assert derived path uses Unit(0x0) from Floppy Unit(0x1)] ****************
2026-06-08 12:57:28.278340 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.068)       0:01:15.985 ***********
2026-06-08 12:57:28.348451 | controller | ok: [instance] => {
2026-06-08 12:57:28.348805 | controller |     "changed": false,
2026-06-08 12:57:28.349145 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:28.349436 | controller | }
2026-06-08 12:57:28.349763 | controller |
2026-06-08 12:57:28.350113 | controller | TASK [Query mock state after floppy fallback] **********************************
2026-06-08 12:57:28.350453 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.072)       0:01:16.058 ***********
2026-06-08 12:57:28.734368 | controller | ok: [instance]
2026-06-08 12:57:28.734404 | controller |
2026-06-08 12:57:28.734409 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 12:57:28.734413 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.385)       0:01:16.444 ***********
2026-06-08 12:57:28.763229 | controller | ok: [instance] => {
2026-06-08 12:57:28.763290 | controller |     "changed": false,
2026-06-08 12:57:28.763301 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:28.763550 | controller | }
2026-06-08 12:57:28.763588 | controller |
2026-06-08 12:57:28.763593 | controller | TASK [Clear vmedia path from previous tests] ***********************************
2026-06-08 12:57:28.763599 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.028)       0:01:16.473 ***********
2026-06-08 12:57:28.783074 | controller | ok: [instance]
2026-06-08 12:57:28.783090 | controller |
2026-06-08 12:57:28.783096 | controller | TASK [Reset mock without Virtual Optical or Floppy Drive] **********************
2026-06-08 12:57:28.783238 | controller | Monday 08 June 2026  12:57:28 +0000 (0:00:00.020)       0:01:16.493 ***********
2026-06-08 12:57:29.132863 | controller | ok: [instance]
2026-06-08 12:57:29.132899 | controller |
2026-06-08 12:57:29.132905 | controller | TASK [Include bm_discover_vmedia_target (generic usb fallback)] ****************
2026-06-08 12:57:29.132910 | controller | Monday 08 June 2026  12:57:29 +0000 (0:00:00.349)       0:01:16.842 ***********
2026-06-08 12:57:29.175752 | controller |
2026-06-08 12:57:29.175790 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 12:57:29.175795 | controller | Monday 08 June 2026  12:57:29 +0000 (0:00:00.042)       0:01:16.885 ***********
2026-06-08 12:57:29.541103 | controller | ok: [instance]
2026-06-08 12:57:29.541143 | controller |
2026-06-08 12:57:29.541148 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 12:57:29.541153 | controller | Monday 08 June 2026  12:57:29 +0000 (0:00:00.365)       0:01:17.250 ***********
2026-06-08 12:57:30.590152 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:30.590206 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:30.590211 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:30.590215 | controller | ok: [instance]
2026-06-08 12:57:30.590219 | controller |
2026-06-08 12:57:30.590223 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 12:57:30.590246 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:01.048)       0:01:18.299 ***********
2026-06-08 12:57:30.632196 | controller | ok: [instance]
2026-06-08 12:57:30.632242 | controller |
2026-06-08 12:57:30.632703 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 12:57:30.632732 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.042)       0:01:18.342 ***********
2026-06-08 12:57:30.673135 | controller | ok: [instance] => {
2026-06-08 12:57:30.673191 | controller |     "msg": [
2026-06-08 12:57:30.673197 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 12:57:30.673202 | 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 12:57:30.673213 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:30.673567 | controller |     ]
2026-06-08 12:57:30.673895 | controller | }
2026-06-08 12:57:30.674223 | controller |
2026-06-08 12:57:30.674598 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 12:57:30.674931 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.039)       0:01:18.381 ***********
2026-06-08 12:57:30.707284 | controller | skipping: [instance]
2026-06-08 12:57:30.707466 | controller |
2026-06-08 12:57:30.707629 | controller | TASK [bm_sno : Find Virtual Optical Drive boot path] ***************************
2026-06-08 12:57:30.707787 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.035)       0:01:18.417 ***********
2026-06-08 12:57:30.765713 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:30.765804 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:30.765977 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:30.766096 | controller | skipping: [instance]
2026-06-08 12:57:30.766206 | controller |
2026-06-08 12:57:30.766321 | controller | TASK [bm_sno : Derive from Virtual Floppy Drive path (Unit 1 -> Unit 0)] *******
2026-06-08 12:57:30.766433 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.058)       0:01:18.475 ***********
2026-06-08 12:57:30.826205 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:30.826264 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:30.826276 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:30.826290 | controller | skipping: [instance]
2026-06-08 12:57:30.826390 | controller |
2026-06-08 12:57:30.826484 | controller | TASK [bm_sno : Fall back to Generic USB Boot path] *****************************
2026-06-08 12:57:30.826606 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.060)       0:01:18.536 ***********
2026-06-08 12:57:30.891313 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-06-08 12:57:30.891386 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-06-08 12:57:30.891403 | controller | ok: [instance] => (item=Generic USB Boot)
2026-06-08 12:57:30.891417 | controller |
2026-06-08 12:57:30.891430 | controller | TASK [bm_sno : Fail if no VirtualMedia boot path found] ************************
2026-06-08 12:57:30.891443 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.064)       0:01:18.600 ***********
2026-06-08 12:57:30.926462 | controller | skipping: [instance]
2026-06-08 12:57:30.926505 | controller |
2026-06-08 12:57:30.926512 | controller | TASK [bm_sno : Show VirtualMedia UEFI boot target] *****************************
2026-06-08 12:57:30.926517 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.035)       0:01:18.636 ***********
2026-06-08 12:57:30.947775 | controller | ok: [instance] => {
2026-06-08 12:57:30.947796 | controller |     "msg": "VirtualMedia UEFI path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:30.947800 | controller | }
2026-06-08 12:57:30.947805 | controller |
2026-06-08 12:57:30.947809 | controller | TASK [bm_sno : Clear pending iDRAC config jobs that block boot override] *******
2026-06-08 12:57:30.947812 | controller | Monday 08 June 2026  12:57:30 +0000 (0:00:00.021)       0:01:18.658 ***********
2026-06-08 12:57:31.291210 | controller | ok: [instance]
2026-06-08 12:57:31.291265 | controller |
2026-06-08 12:57:31.291458 | controller | TASK [bm_sno : Wait for iDRAC to settle after clearing jobs] *******************
2026-06-08 12:57:31.291501 | controller | Monday 08 June 2026  12:57:31 +0000 (0:00:00.342)       0:01:19.001 ***********
2026-06-08 12:57:41.325719 | controller | Pausing for 10 seconds
2026-06-08 12:57:41.325758 | controller | ok: [instance]
2026-06-08 12:57:41.325765 | controller |
2026-06-08 12:57:41.325770 | controller | TASK [bm_sno : Set one-time boot from Virtual Optical Drive] *******************
2026-06-08 12:57:41.325776 | controller | Monday 08 June 2026  12:57:41 +0000 (0:00:10.034)       0:01:29.035 ***********
2026-06-08 12:57:41.674901 | controller | ok: [instance]
2026-06-08 12:57:41.674941 | controller |
2026-06-08 12:57:41.674952 | controller | TASK [bm_sno : Verify boot override was applied] *******************************
2026-06-08 12:57:41.674979 | controller | Monday 08 June 2026  12:57:41 +0000 (0:00:00.349)       0:01:29.384 ***********
2026-06-08 12:57:42.041223 | controller | ok: [instance]
2026-06-08 12:57:42.041274 | controller |
2026-06-08 12:57:42.041453 | controller | TASK [bm_sno : Assert boot override is set] ************************************
2026-06-08 12:57:42.041488 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.366)       0:01:29.751 ***********
2026-06-08 12:57:42.099900 | controller | ok: [instance] => {
2026-06-08 12:57:42.099941 | controller |     "changed": false,
2026-06-08 12:57:42.099967 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:42.099974 | controller | }
2026-06-08 12:57:42.099980 | controller |
2026-06-08 12:57:42.099988 | controller | TASK [bm_sno : Show resolved boot path] ****************************************
2026-06-08 12:57:42.099994 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.057)       0:01:29.809 ***********
2026-06-08 12:57:42.123189 | controller | ok: [instance] => {
2026-06-08 12:57:42.123241 | controller |     "msg": "Resolved boot path: VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:42.123249 | controller | }
2026-06-08 12:57:42.123478 | controller |
2026-06-08 12:57:42.123512 | controller | TASK [bm_sno : Verify VirtualMedia is still inserted] **************************
2026-06-08 12:57:42.123517 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.023)       0:01:29.833 ***********
2026-06-08 12:57:42.501679 | controller | ok: [instance]
2026-06-08 12:57:42.501721 | controller |
2026-06-08 12:57:42.501728 | controller | TASK [bm_sno : Assert VirtualMedia ISO is mounted] *****************************
2026-06-08 12:57:42.501734 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.378)       0:01:30.211 ***********
2026-06-08 12:57:42.542533 | controller | ok: [instance] => {
2026-06-08 12:57:42.542778 | controller |     "changed": false,
2026-06-08 12:57:42.543030 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:42.543191 | controller | }
2026-06-08 12:57:42.543361 | controller |
2026-06-08 12:57:42.543493 | controller | TASK [Assert Generic USB Boot path was used] ***********************************
2026-06-08 12:57:42.543614 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.041)       0:01:30.252 ***********
2026-06-08 12:57:42.585003 | controller | ok: [instance] => {
2026-06-08 12:57:42.585194 | controller |     "changed": false,
2026-06-08 12:57:42.585336 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:42.585503 | controller | }
2026-06-08 12:57:42.585662 | controller |
2026-06-08 12:57:42.585813 | controller | TASK [Query mock state after generic usb fallback] *****************************
2026-06-08 12:57:42.586011 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.042)       0:01:30.295 ***********
2026-06-08 12:57:42.932166 | controller | ok: [instance]
2026-06-08 12:57:42.932323 | controller |
2026-06-08 12:57:42.932452 | controller | TASK [Assert boot override was set] ********************************************
2026-06-08 12:57:42.932577 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.347)       0:01:30.642 ***********
2026-06-08 12:57:42.961136 | controller | ok: [instance] => {
2026-06-08 12:57:42.961297 | controller |     "changed": false,
2026-06-08 12:57:42.961427 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:42.961551 | controller | }
2026-06-08 12:57:42.961679 | controller |
2026-06-08 12:57:42.961840 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-06-08 12:57:42.962021 | controller | Monday 08 June 2026  12:57:42 +0000 (0:00:00.028)       0:01:30.671 ***********
2026-06-08 12:57:43.293523 | controller | ok: [instance]
2026-06-08 12:57:43.293564 | controller |
2026-06-08 12:57:43.293581 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-06-08 12:57:43.293587 | controller | Monday 08 June 2026  12:57:43 +0000 (0:00:00.331)       0:01:31.003 ***********
2026-06-08 12:57:43.328102 | controller |
2026-06-08 12:57:43.328151 | controller | TASK [bm_sno : Fetch UEFI boot option IDs] *************************************
2026-06-08 12:57:43.328157 | controller | Monday 08 June 2026  12:57:43 +0000 (0:00:00.034)       0:01:31.038 ***********
2026-06-08 12:57:43.693622 | controller | ok: [instance]
2026-06-08 12:57:43.693671 | controller |
2026-06-08 12:57:43.693680 | controller | TASK [bm_sno : Fetch each UEFI boot option detail] *****************************
2026-06-08 12:57:43.693689 | controller | Monday 08 June 2026  12:57:43 +0000 (0:00:00.365)       0:01:31.403 ***********
2026-06-08 12:57:45.434224 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:45.434272 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:45.434277 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:45.434280 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:45.435174 | controller | ok: [instance] => (item=None)
2026-06-08 12:57:45.435227 | controller | ok: [instance]
2026-06-08 12:57:45.435239 | controller |
2026-06-08 12:57:45.435249 | controller | TASK [bm_sno : Build list of known UEFI device paths] **************************
2026-06-08 12:57:45.435258 | controller | Monday 08 June 2026  12:57:45 +0000 (0:00:01.740)       0:01:33.143 ***********
2026-06-08 12:57:45.483197 | controller | ok: [instance]
2026-06-08 12:57:45.483624 | controller |
2026-06-08 12:57:45.483657 | controller | TASK [bm_sno : Show all UEFI boot options] *************************************
2026-06-08 12:57:45.483667 | controller | Monday 08 June 2026  12:57:45 +0000 (0:00:00.049)       0:01:33.192 ***********
2026-06-08 12:57:45.532190 | controller | ok: [instance] => {
2026-06-08 12:57:45.532251 | controller |     "msg": [
2026-06-08 12:57:45.532262 | controller |         "PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA)",
2026-06-08 12:57:45.532275 | controller |         "Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1)",
2026-06-08 12:57:45.532355 | controller |         "Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)",
2026-06-08 12:57:45.532723 | 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 12:57:45.533106 | controller |         "Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-06-08 12:57:45.533449 | controller |     ]
2026-06-08 12:57:45.534444 | controller | }
2026-06-08 12:57:45.535010 | controller |
2026-06-08 12:57:45.535181 | controller | TASK [bm_sno : Validate user-provided VirtualMedia UEFI path] ******************
2026-06-08 12:57:45.535319 | controller | Monday 08 June 2026  12:57:45 +0000 (0:00:00.047)       0:01:33.240 ***********
2026-06-08 12:57:45.582537 | controller | fatal: [instance]: FAILED! => {
2026-06-08 12:57:45.582886 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-06-08 12:57:45.583260 | controller |     "changed": false,
2026-06-08 12:57:45.583588 | controller |     "evaluated_to": false,
2026-06-08 12:57:45.583997 | 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 12:57:45.584372 | controller | }
2026-06-08 12:57:45.591448 | controller |
2026-06-08 12:57:45.591718 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-06-08 12:57:45.591963 | controller | Monday 08 June 2026  12:57:45 +0000 (0:00:00.061)       0:01:33.301 ***********
2026-06-08 12:57:45.646740 | controller | ok: [instance] => {
2026-06-08 12:57:45.647028 | controller |     "changed": false,
2026-06-08 12:57:45.647271 | controller |     "msg": "All assertions passed"
2026-06-08 12:57:45.647544 | controller | }
2026-06-08 12:57:45.647790 | controller |
2026-06-08 12:57:45.648057 | controller | PLAY RECAP *********************************************************************
2026-06-08 12:57:45.648310 | controller | instance                   : ok=168  changed=0    unreachable=0    failed=0    skipped=28   rescued=5    ignored=0
2026-06-08 12:57:45.648586 | controller |
2026-06-08 12:57:45.648869 | controller | Monday 08 June 2026  12:57:45 +0000 (0:00:00.054)       0:01:33.356 ***********
2026-06-08 12:57:45.649124 | controller | ===============================================================================
2026-06-08 12:57:45.649354 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.05s
2026-06-08 12:57:45.649578 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 12:57:45.649799 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.04s
2026-06-08 12:57:45.650051 | controller | bm_sno : Wait for iDRAC to settle after clearing jobs ------------------ 10.03s
2026-06-08 12:57:45.650313 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.03s
2026-06-08 12:57:45.650531 | controller | bm_sno : Wait for VirtualMedia eject to settle -------------------------- 5.03s
2026-06-08 12:57:45.650749 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.82s
2026-06-08 12:57:45.651011 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.74s
2026-06-08 12:57:45.651229 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.72s
2026-06-08 12:57:45.651446 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.53s
2026-06-08 12:57:45.651674 | controller | bm_sno : Fetch each UEFI boot option detail ----------------------------- 1.05s
2026-06-08 12:57:45.651895 | controller | bm_sno : Query current power state -------------------------------------- 0.50s
2026-06-08 12:57:45.652153 | controller | Reset mock to power Off ------------------------------------------------- 0.49s
2026-06-08 12:57:45.652375 | controller | bm_sno : Power on bare metal host --------------------------------------- 0.43s
2026-06-08 12:57:45.652619 | controller | bm_sno : Wait for host POST to complete --------------------------------- 0.43s
2026-06-08 12:57:45.652840 | controller | bm_sno : Power on bare metal host --------------------------------------- 0.41s
2026-06-08 12:57:45.653093 | controller | bm_sno : Clear pending iDRAC config jobs that block boot override ------- 0.41s
2026-06-08 12:57:45.653323 | controller | bm_sno : Verify boot override was applied ------------------------------- 0.40s
2026-06-08 12:57:45.653540 | controller | Reset mock with VirtualMedia inserted ----------------------------------- 0.40s
2026-06-08 12:57:45.653755 | controller | bm_sno : Set one-time boot from Virtual Optical Drive ------------------- 0.40s
2026-06-08 12:57:45.771833 | controller | INFO     Running bm_redfish > cleanup
2026-06-08 12:57:46.323014 | controller |
2026-06-08 12:57:46.323186 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-06-08 12:57:46.323295 | controller |
2026-06-08 12:57:46.323635 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-06-08 12:57:46.323652 | controller | Monday 08 June 2026  12:57:46 +0000 (0:00:00.025)       0:00:00.025 ***********
2026-06-08 12:57:46.725004 | controller | ok: [instance]
2026-06-08 12:57:46.725062 | controller |
2026-06-08 12:57:46.725074 | controller | TASK [Show mock server log] ****************************************************
2026-06-08 12:57:46.725083 | controller | Monday 08 June 2026  12:57:46 +0000 (0:00:00.402)       0:00:00.427 ***********
2026-06-08 12:57:46.949757 | controller | ok: [instance]
2026-06-08 12:57:46.949810 | controller |
2026-06-08 12:57:46.949818 | controller | TASK [Print mock server log] ***************************************************
2026-06-08 12:57:46.949858 | controller | Monday 08 June 2026  12:57:46 +0000 (0:00:00.224)       0:00:00.652 ***********
2026-06-08 12:57:46.987145 | controller | ok: [instance] => {
2026-06-08 12:57:46.987202 | controller |     "_mock_log.stdout_lines": [
2026-06-08 12:57:46.987211 | controller |         "Mock iDRAC listening on https://0.0.0.0:8443",
2026-06-08 12:57:46.987219 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987234 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987241 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987265 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987335 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987465 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987593 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 12:57:46.987716 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.987836 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988028 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988169 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988292 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988419 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988546 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988709 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.988837 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 12:57:46.988978 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989119 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989245 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989373 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989509 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 12:57:46.989630 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989756 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.989879 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990090 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990216 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990344 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990469 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990595 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990716 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990839 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.990980 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991122 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1/Bios/Settings HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991238 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/Jobs HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991366 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991493 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991620 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 12:57:46.991745 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.991868 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992025 | controller |         "[mock-idrac] \"POST /redfish/v1/Systems/System.Embedded.1/Actions/ComputerSystem.Reset HTTP/1.1\" 204 -",
2026-06-08 12:57:46.992147 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992273 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992396 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992520 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/Bios HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992690 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.992818 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 12:57:46.992941 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993087 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993215 | controller |         "[mock-idrac] \"POST /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD/Actions/VirtualMedia.EjectMedia HTTP/1.1\" 204 -",
2026-06-08 12:57:46.993337 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993460 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993584 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993708 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993835 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.993989 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.994106 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.994538 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.994663 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 12:57:46.994783 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.994904 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995059 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995175 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995299 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995441 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995559 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995685 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995810 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.995963 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996093 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996228 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996352 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996479 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996626 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996753 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.996880 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997030 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997151 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997276 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997401 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997531 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997652 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997778 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.997902 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998052 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998170 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998292 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998417 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998541 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998665 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998789 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.998915 | controller |         "[mock-idrac] \"POST /redfish/v1/Dell/Managers/iDRAC.Embedded.1/DellJobService/Actions/DellJobService.DeleteJobQueue HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999064 | controller |         "[mock-idrac] \"PATCH /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999188 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999318 | controller |         "[mock-idrac] \"GET /redfish/v1/Managers/iDRAC.Embedded.1/VirtualMedia/CD HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999441 | controller |         "[mock-idrac] \"GET /test/state HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999564 | controller |         "[mock-idrac] \"POST /test/reset HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999687 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999813 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0001 HTTP/1.1\" 200 -",
2026-06-08 12:57:46.999938 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0003 HTTP/1.1\" 200 -",
2026-06-08 12:57:47.000084 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0004 HTTP/1.1\" 200 -",
2026-06-08 12:57:47.000206 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0005 HTTP/1.1\" 200 -",
2026-06-08 12:57:47.000329 | controller |         "[mock-idrac] \"GET /redfish/v1/Systems/System.Embedded.1/BootOptions/Boot0006 HTTP/1.1\" 200 -"
2026-06-08 12:57:47.000447 | controller |     ]
2026-06-08 12:57:47.000565 | controller | }
2026-06-08 12:57:47.000764 | controller |
2026-06-08 12:57:47.000884 | controller | PLAY RECAP *********************************************************************
2026-06-08 12:57:47.001049 | controller | instance                   : ok=3    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-06-08 12:57:47.001157 | controller |
2026-06-08 12:57:47.001283 | controller | Monday 08 June 2026  12:57:46 +0000 (0:00:00.049)       0:00:00.702 ***********
2026-06-08 12:57:47.001404 | controller | ===============================================================================
2026-06-08 12:57:47.001527 | controller | Stop mock iDRAC server -------------------------------------------------- 0.40s
2026-06-08 12:57:47.001652 | controller | Show mock server log ---------------------------------------------------- 0.22s
2026-06-08 12:57:47.001775 | controller | Print mock server log --------------------------------------------------- 0.05s
2026-06-08 12:57:47.099611 | controller | INFO     Writing /tmp/report.html report.
2026-06-08 12:57:47.267702 | controller | ok: Runtime: 0:01:39.831460
2026-06-08 12:57:47.282784 | 
2026-06-08 12:57:47.282866 | PLAY RECAP
2026-06-08 12:57:47.282927 | controller | ok: 4 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-06-08 12:57:47.282955 | 
2026-06-08 12:57:47.435715 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-06-08 12:57:47.438407 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 12:57:48.133488 | 
2026-06-08 12:57:48.133789 | PLAY [Ensure ci-framework-data base directories exist on all nodes]
2026-06-08 12:57:48.157482 | 
2026-06-08 12:57:48.157688 | TASK [Create ci-framework-data/logs directory if missing]
2026-06-08 12:57:48.611710 | controller | ok
2026-06-08 12:57:48.657811 | 
2026-06-08 12:57:48.657951 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-06-08 12:57:48.665863 | 
2026-06-08 12:57:48.666023 | TASK [Filter out host if needed]
2026-06-08 12:57:48.677622 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-06-08 12:57:48.682113 | 
2026-06-08 12:57:48.682188 | TASK [Ensure file is present]
2026-06-08 12:57:49.102924 | controller | ok
2026-06-08 12:57:49.114713 | 
2026-06-08 12:57:49.114905 | TASK [Manage molecule report file]
2026-06-08 12:57:49.659821 | controller | ok: Runtime: 0:00:00.013715
2026-06-08 12:57:49.668912 | 
2026-06-08 12:57:49.669048 | TASK [Check if we get ci-framework-data basedir]
2026-06-08 12:57:49.917535 | controller | ok
2026-06-08 12:57:49.926901 | 
2026-06-08 12:57:49.927072 | TASK [Create ci-framework-data log directory for zuul]
2026-06-08 12:57:50.153535 | controller | changed
2026-06-08 12:57:50.163618 | 
2026-06-08 12:57:50.163798 | TASK [Copy ci-framework interesting files]
2026-06-08 12:57:50.438340 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-06-08 12:57:50.711193 | controller | ok: Runtime: 0:00:00.013357
2026-06-08 12:57:50.719818 | 
2026-06-08 12:57:50.719997 | TASK [Get SELinux listing]
2026-06-08 12:57:51.269012 | controller | ok: Runtime: 0:00:00.015894
2026-06-08 12:57:51.278074 | 
2026-06-08 12:57:51.278209 | TASK [Generate log index]
2026-06-08 12:57:52.234491 | controller | changed
2026-06-08 12:57:52.241023 | 
2026-06-08 12:57:52.241117 | TASK [Get some env related data]
2026-06-08 12:57:52.887812 | controller | /home/zuul/.local/bin/ansible
2026-06-08 12:57:53.775413 | controller | ok: Runtime: 0:00:01.131935
2026-06-08 12:57:53.857847 | 
2026-06-08 12:57:53.858108 | TASK [Generate list of logs to collect in home directory]
2026-06-08 12:57:54.196299 | controller | ok: All paths examined
2026-06-08 12:57:54.204312 | 
2026-06-08 12:57:54.204440 | LOOP [Copy logs from home directory]
2026-06-08 12:57:54.609529 | controller | changed:
2026-06-08 12:57:54.609845 | controller | {
2026-06-08 12:57:54.609905 | controller |   "atime": 1780923345.7815964,
2026-06-08 12:57:54.609945 | controller |   "ctime": 1780923364.5380766,
2026-06-08 12:57:54.609982 | controller |   "dev": 64513,
2026-06-08 12:57:54.610019 | controller |   "gid": 1000,
2026-06-08 12:57:54.610054 | controller |   "gr_name": "zuul",
2026-06-08 12:57:54.610089 | controller |   "inode": 247745,
2026-06-08 12:57:54.610124 | controller |   "isblk": false,
2026-06-08 12:57:54.610158 | controller |   "ischr": false,
2026-06-08 12:57:54.610192 | controller |   "isdir": false,
2026-06-08 12:57:54.610224 | controller |   "isfifo": false,
2026-06-08 12:57:54.610257 | controller |   "isgid": false,
2026-06-08 12:57:54.610290 | controller |   "islnk": false,
2026-06-08 12:57:54.610323 | controller |   "isreg": true,
2026-06-08 12:57:54.610355 | controller |   "issock": false,
2026-06-08 12:57:54.610397 | controller |   "isuid": false,
2026-06-08 12:57:54.610432 | controller |   "mode": "0644",
2026-06-08 12:57:54.610467 | controller |   "mtime": 1780923364.5380766,
2026-06-08 12:57:54.610502 | controller |   "nlink": 1,
2026-06-08 12:57:54.610537 | controller |   "path": "/home/zuul/ansible.log",
2026-06-08 12:57:54.610603 | controller |   "pw_name": "zuul",
2026-06-08 12:57:54.610652 | controller |   "rgrp": true,
2026-06-08 12:57:54.610690 | controller |   "roth": true,
2026-06-08 12:57:54.610730 | controller |   "rusr": true,
2026-06-08 12:57:54.610766 | controller |   "size": 6749,
2026-06-08 12:57:54.610800 | controller |   "uid": 1000,
2026-06-08 12:57:54.610835 | controller |   "wgrp": false,
2026-06-08 12:57:54.610871 | controller |   "woth": false,
2026-06-08 12:57:54.610905 | controller |   "wusr": true,
2026-06-08 12:57:54.610938 | controller |   "xgrp": false,
2026-06-08 12:57:54.610972 | controller |   "xoth": false,
2026-06-08 12:57:54.611006 | controller |   "xusr": false
2026-06-08 12:57:54.611039 | controller | }
2026-06-08 12:57:54.623683 | 
2026-06-08 12:57:54.623851 | TASK [Copy crio stats log file]
2026-06-08 12:57:54.648381 | controller | skipping: Conditional result was False
2026-06-08 12:57:54.652969 | 
2026-06-08 12:57:54.653040 | TASK [Get SELinux related data]
2026-06-08 12:57:54.918623 | controller | <no matches>
2026-06-08 12:57:55.184161 | controller | ERROR
2026-06-08 12:57:55.184409 | controller | {
2026-06-08 12:57:55.184468 | controller |   "delta": "0:00:00.013574",
2026-06-08 12:57:55.184523 | controller |   "end": "2026-06-08 12:57:54.919781",
2026-06-08 12:57:55.184563 | controller |   "msg": "non-zero return code",
2026-06-08 12:57:55.184661 | controller |   "rc": 1,
2026-06-08 12:57:55.184699 | controller |   "start": "2026-06-08 12:57:54.906207"
2026-06-08 12:57:55.184733 | controller | }
2026-06-08 12:57:55.184779 | controller | ERROR: Ignoring Errors
2026-06-08 12:57:55.192710 | 
2026-06-08 12:57:55.192881 | TASK [Create system configuration directory]
2026-06-08 12:57:55.453864 | controller | changed
2026-06-08 12:57:55.462040 | 
2026-06-08 12:57:55.462416 | TASK [Get some of the system configurations]
2026-06-08 12:57:56.009913 | controller | ok: Runtime: 0:00:00.016671
2026-06-08 12:57:56.015280 | 
2026-06-08 12:57:56.015373 | TASK [Copy generated documentation if available]
2026-06-08 12:57:56.051145 | controller | skipping: Conditional result was False
2026-06-08 12:57:56.060570 | 
2026-06-08 12:57:56.060798 | TASK [Copy generated AsciiDoc documentation if available]
2026-06-08 12:57:56.097759 | controller | skipping: Conditional result was False
2026-06-08 12:57:56.108306 | 
2026-06-08 12:57:56.108473 | TASK [Compress logs bigger than 2MB]
2026-06-08 12:57:56.665305 | controller | ok: Runtime: 0:00:00.007972
2026-06-08 12:57:56.673035 | 
2026-06-08 12:57:56.673170 | TASK [Copy files from workspace on node]
2026-06-08 12:57:56.707136 | controller | ok
2026-06-08 12:57:56.744750 | 
2026-06-08 12:57:56.744889 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 12:57:56.780475 | controller | skipping: Conditional result was False
2026-06-08 12:57:56.789841 | 
2026-06-08 12:57:56.789989 | TASK [fetch-output : Set log path for single node]
2026-06-08 12:57:56.838053 | controller | ok
2026-06-08 12:57:56.846240 | 
2026-06-08 12:57:56.846376 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 12:57:57.137112 | controller -> localhost | changed: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/logs"
2026-06-08 12:57:57.138219 | controller -> localhost | changed: All items complete
2026-06-08 12:57:57.138321 | 
2026-06-08 12:57:57.385224 | controller -> localhost | changed: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/artifacts"
2026-06-08 12:57:57.636740 | controller -> localhost | changed: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/docs"
2026-06-08 12:57:57.658673 | 
2026-06-08 12:57:57.658893 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 12:57:58.454880 | controller | changed:
2026-06-08 12:57:58.455201 | controller | .d..t...... ./
2026-06-08 12:57:58.455259 | controller | >f+++++++++ README.html
2026-06-08 12:57:58.455303 | controller | >f+++++++++ ansible-execution.log
2026-06-08 12:57:58.455342 | controller | >f+++++++++ ansible.log
2026-06-08 12:57:58.455385 | controller | >f+++++++++ dmesg.log
2026-06-08 12:57:58.455424 | controller | >f+++++++++ installed-pkgs.log
2026-06-08 12:57:58.455460 | controller | >f+++++++++ python.log
2026-06-08 12:57:58.455497 | controller | >f+++++++++ registries.conf
2026-06-08 12:57:58.455533 | controller | >f+++++++++ report.html
2026-06-08 12:57:58.455569 | controller | >f+++++++++ selinux-denials.log
2026-06-08 12:57:58.455648 | controller | >f+++++++++ selinux-listing.log
2026-06-08 12:57:58.455686 | controller | cd+++++++++ ci-framework-data/
2026-06-08 12:57:58.455722 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-06-08 12:57:58.455758 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-06-08 12:57:58.455794 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-06-08 12:57:58.455830 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-06-08 12:57:58.455865 | controller | cd+++++++++ ci-framework-data/logs/
2026-06-08 12:57:58.455901 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-06-08 12:57:58.455937 | controller | cd+++++++++ registries.conf.d/
2026-06-08 12:57:58.455973 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-06-08 12:57:58.456019 | controller | cd+++++++++ system-config/
2026-06-08 12:57:58.456056 | controller | cd+++++++++ system-config/libvirt/
2026-06-08 12:57:58.456091 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-06-08 12:57:58.456126 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-06-08 12:57:59.081254 | controller | changed: .d..t...... ./
2026-06-08 12:57:59.624550 | controller | changed: .d..t...... ./
2026-06-08 12:57:59.660530 | 
2026-06-08 12:57:59.660821 | TASK [Return artifact to Zuul]
2026-06-08 12:57:59.708715 | controller | ok
2026-06-08 12:57:59.712400 | 
2026-06-08 12:57:59.712514 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-06-08 12:57:59.712765 | 
2026-06-08 12:57:59.712837 | PLAY RECAP
2026-06-08 12:57:59.712918 | controller | ok: 19 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-06-08 12:57:59.712962 | 
2026-06-08 12:57:59.883473 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-06-08 12:57:59.885857 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 12:58:00.513061 | 
2026-06-08 12:58:00.513196 | PLAY [all]
2026-06-08 12:58:00.522482 | 
2026-06-08 12:58:00.522557 | TASK [include_role : fetch-output]
2026-06-08 12:58:00.569987 | controller | ok
2026-06-08 12:58:00.587690 | 
2026-06-08 12:58:00.587796 | TASK [fetch-output : Set log path for multiple nodes]
2026-06-08 12:58:00.663980 | controller | skipping: Conditional result was False
2026-06-08 12:58:00.668685 | 
2026-06-08 12:58:00.668769 | TASK [fetch-output : Set log path for single node]
2026-06-08 12:58:00.716699 | controller | ok
2026-06-08 12:58:00.720253 | 
2026-06-08 12:58:00.720315 | LOOP [fetch-output : Ensure local output dirs]
2026-06-08 12:58:01.200894 | controller -> localhost | ok: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/logs"
2026-06-08 12:58:01.456158 | controller -> localhost | ok: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/artifacts"
2026-06-08 12:58:01.733874 | controller -> localhost | ok: "/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/docs"
2026-06-08 12:58:01.754719 | 
2026-06-08 12:58:01.754924 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-06-08 12:58:02.520828 | controller | ok
2026-06-08 12:58:02.521182 | controller | ok: All items complete
2026-06-08 12:58:02.521241 | 
2026-06-08 12:58:03.072707 | controller | ok
2026-06-08 12:58:03.632930 | controller | ok
2026-06-08 12:58:03.649361 | 
2026-06-08 12:58:03.649505 | TASK [include_role : fetch-output-openshift]
2026-06-08 12:58:03.673927 | controller | skipping: Conditional result was False
2026-06-08 12:58:03.680155 | 
2026-06-08 12:58:03.680244 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-06-08 12:58:04.224663 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.011064
2026-06-08 12:58:04.523009 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.011925
2026-06-08 12:58:04.534971 | 
2026-06-08 12:58:04.535096 | PLAY [all]
2026-06-08 12:58:04.539749 | 
2026-06-08 12:58:04.539815 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-06-08 12:58:05.062540 | controller | changed
2026-06-08 12:58:05.066780 | 
2026-06-08 12:58:05.066828 | PLAY RECAP
2026-06-08 12:58:05.066866 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-06-08 12:58:05.066884 | 
2026-06-08 12:58:05.178225 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-06-08 12:58:05.180527 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-06-08 12:58:05.827960 | 
2026-06-08 12:58:05.828072 | PLAY [localhost]
2026-06-08 12:58:05.838391 | 
2026-06-08 12:58:05.838489 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-06-08 12:58:06.304207 | localhost | changed
2026-06-08 12:58:06.323370 | 
2026-06-08 12:58:06.323698 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-06-08 12:58:06.366430 | localhost | ok
2026-06-08 12:58:06.379749 | 
2026-06-08 12:58:06.379885 | TASK [add-fileserver : Create SSH private key tempfile]
2026-06-08 12:58:06.827535 | localhost | changed
2026-06-08 12:58:06.837203 | 
2026-06-08 12:58:06.837346 | TASK [add-fileserver : Create SSH private key from secret]
2026-06-08 12:58:07.790920 | localhost | changed
2026-06-08 12:58:07.796418 | 
2026-06-08 12:58:07.796502 | TASK [add-fileserver : Add fileserver ssh key]
2026-06-08 12:58:08.283754 | localhost | Identity added: /var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/tmp/ansible.h94jw6kz (/var/lib/zuul/builds/bc42071673f54606b8bae9f0aa265917/work/tmp/ansible.h94jw6kz)
2026-06-08 12:58:08.284013 | localhost | ok: Runtime: 0:00:00.016257
2026-06-08 12:58:08.288435 | 
2026-06-08 12:58:08.288512 | TASK [add-fileserver : Remove SSH private key from disk]
2026-06-08 12:58:08.630840 | localhost | ok: Runtime: 0:00:00.010023
2026-06-08 12:58:08.639553 | 
2026-06-08 12:58:08.639742 | TASK [add-fileserver : Add fileserver to inventory]
2026-06-08 12:58:08.724318 | localhost | changed
2026-06-08 12:58:08.731015 | 
2026-06-08 12:58:08.731103 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-06-08 12:58:09.231198 | localhost | changed
2026-06-08 12:58:09.243127 | 
2026-06-08 12:58:09.243239 | PLAY [localhost]
2026-06-08 12:58:09.251622 | 
2026-06-08 12:58:09.251781 | TASK [Generate bulk log download script]
2026-06-08 12:58:09.272994 | localhost | ok
2026-06-08 12:58:09.293356 | 
2026-06-08 12:58:09.293488 | TASK [local-log-download : Check API endpoint is defined]
2026-06-08 12:58:09.324857 | localhost | ok: All assertions passed
2026-06-08 12:58:09.331956 | 
2026-06-08 12:58:09.332076 | TASK [local-log-download : Create download script]
2026-06-08 12:58:09.897599 | localhost -> localhost | changed
2026-06-08 12:58:09.956881 | 
2026-06-08 12:58:09.957038 | TASK [Register quick-download link]
2026-06-08 12:58:09.999916 | localhost | ok
2026-06-08 12:58:10.004462 | 
2026-06-08 12:58:10.004615 | PLAY [a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com]
2026-06-08 12:58:10.014854 | 
2026-06-08 12:58:10.014980 | TASK [Set zuul-log-path fact]
2026-06-08 12:58:10.034350 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 12:58:10.047660 | 
2026-06-08 12:58:10.047790 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-06-08 12:58:10.086063 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | ok
2026-06-08 12:58:10.089106 | 
2026-06-08 12:58:10.089184 | TASK [upload-logs : Create log directories]
2026-06-08 12:58:11.312821 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | changed
2026-06-08 12:58:11.315319 | 
2026-06-08 12:58:11.315404 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-06-08 12:58:11.691634 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com -> localhost | ok: Runtime: 0:00:00.012835
2026-06-08 12:58:11.695770 | 
2026-06-08 12:58:11.695853 | TASK [upload-logs : Upload logs to log server]
2026-06-08 12:58:13.857524 | a71a93e18f1524007a0994a866a4da93-48298913.us-east-1.elb.amazonaws.com | Output suppressed because no_log was given
2026-06-08 12:58:13.860873 | 
2026-06-08 12:58:13.861000 | LOOP [upload-logs : Compress console log and json output]