2026-03-12 10:37:55.325252 | Job console starting...
2026-03-12 10:37:55.559423 | Updating repositories
2026-03-12 10:37:55.584414 | Preparing job workspace
2026-03-12 10:38:04.066795 | Running Ansible setup...
2026-03-12 10:38:07.437798 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-12 10:38:07.903390 | 
2026-03-12 10:38:07.903485 | PLAY [localhost]
2026-03-12 10:38:07.911306 | 
2026-03-12 10:38:07.911375 | TASK [Gathering Facts]
2026-03-12 10:38:08.649556 | localhost | ok
2026-03-12 10:38:08.662656 | 
2026-03-12 10:38:08.662748 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-03-12 10:38:08.960028 | localhost -> localhost | changed
2026-03-12 10:38:08.965035 | 
2026-03-12 10:38:08.965100 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-03-12 10:38:09.606340 | localhost -> localhost | changed
2026-03-12 10:38:09.614260 | 
2026-03-12 10:38:09.614346 | TASK [Setup log path fact]
2026-03-12 10:38:09.630985 | localhost | ok
2026-03-12 10:38:09.641594 | 
2026-03-12 10:38:09.641659 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-12 10:38:09.668421 | localhost | ok
2026-03-12 10:38:09.675714 | 
2026-03-12 10:38:09.675780 | TASK [emit-job-header : Print job information]
2026-03-12 10:38:09.702798 | # Job Information
2026-03-12 10:38:09.702917 | Ansible Version: 2.15.12
2026-03-12 10:38:09.702955 | Job: cifmw-molecule-reproducer
2026-03-12 10:38:09.702980 | Pipeline: github-check
2026-03-12 10:38:09.702999 | Executor: ibm-bm3-ze.softwarefactory-project.io
2026-03-12 10:38:09.703019 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3739
2026-03-12 10:38:09.703038 | Log URL (when completed): https://logserver.rdoproject.org/a2b/rdoproject.org/a2b351dfb56646f4bf330d423e352d33/
2026-03-12 10:38:09.703057 | Event ID: 61f4b890-1dff-11f1-8b2f-280d5d10760e
2026-03-12 10:38:09.706689 | 
2026-03-12 10:38:09.706752 | LOOP [emit-job-header : Print node information]
2026-03-12 10:38:09.786458 | localhost | ok:
2026-03-12 10:38:09.786609 | localhost | # Node Information
2026-03-12 10:38:09.786638 | localhost | Inventory Hostname: controller
2026-03-12 10:38:09.786663 | localhost | Hostname: np0005645249
2026-03-12 10:38:09.786684 | localhost | Username: zuul
2026-03-12 10:38:09.786704 | localhost | Distro: CentOS 9
2026-03-12 10:38:09.786722 | localhost | Provider: ibm-bm3-nodepool
2026-03-12 10:38:09.786740 | localhost | Region: regionOne
2026-03-12 10:38:09.786756 | localhost | Label: centos-9-stream-crc-2-48-0-xxl-ibm
2026-03-12 10:38:09.786772 | localhost | Product Name: OpenStack Compute
2026-03-12 10:38:09.786789 | localhost | Interface IP: 192.168.25.5
2026-03-12 10:38:09.808633 | 
2026-03-12 10:38:09.808693 | PLAY [all]
2026-03-12 10:38:09.814292 | 
2026-03-12 10:38:09.814356 | TASK [Gather network facts]
2026-03-12 10:38:10.207885 | controller | ok
2026-03-12 10:38:10.220169 | 
2026-03-12 10:38:10.220225 | TASK [include_role : start-zuul-console]
2026-03-12 10:38:10.236984 | controller | ok
2026-03-12 10:38:10.253297 | 
2026-03-12 10:38:10.253357 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-03-12 10:38:10.593928 | controller | ok
2026-03-12 10:38:10.601582 | 
2026-03-12 10:38:10.601639 | TASK [include_role : add-build-sshkey]
2026-03-12 10:38:10.618769 | controller | ok
2026-03-12 10:38:10.630190 | 
2026-03-12 10:38:10.630249 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-03-12 10:38:10.805023 | controller -> localhost | ok
2026-03-12 10:38:10.809927 | 
2026-03-12 10:38:10.810000 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-03-12 10:38:10.827400 | controller | ok
2026-03-12 10:38:10.839408 | controller | included: /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-03-12 10:38:10.844611 | 
2026-03-12 10:38:10.844667 | TASK [add-build-sshkey : Create Temp SSH key]
2026-03-12 10:38:11.343161 | controller -> localhost | Generating public/private rsa key pair.
2026-03-12 10:38:11.343352 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/a2b351dfb56646f4bf330d423e352d33_id_rsa.
2026-03-12 10:38:11.343386 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/a2b351dfb56646f4bf330d423e352d33_id_rsa.pub.
2026-03-12 10:38:11.343409 | controller -> localhost | The key fingerprint is:
2026-03-12 10:38:11.343429 | controller -> localhost | SHA256:f7qRPFtVDZcrd/vTOCYyuD61/VoyDbhpOjPjM12zGjI zuul-build-sshkey
2026-03-12 10:38:11.343448 | controller -> localhost | The key's randomart image is:
2026-03-12 10:38:11.343467 | controller -> localhost | +---[RSA 3072]----+
2026-03-12 10:38:11.343484 | controller -> localhost | |              . o|
2026-03-12 10:38:11.343501 | controller -> localhost | |               +.|
2026-03-12 10:38:11.343518 | controller -> localhost | |                +|
2026-03-12 10:38:11.343534 | controller -> localhost | |           . . +.|
2026-03-12 10:38:11.343551 | controller -> localhost | |        S . . + o|
2026-03-12 10:38:11.343566 | controller -> localhost | |         o.+o+ . |
2026-03-12 10:38:11.343582 | controller -> localhost | |        E+@+=oo.o|
2026-03-12 10:38:11.343601 | controller -> localhost | |        X==O+++.o|
2026-03-12 10:38:11.343618 | controller -> localhost | |       o=X==.=...|
2026-03-12 10:38:11.343634 | controller -> localhost | +----[SHA256]-----+
2026-03-12 10:38:11.343675 | controller -> localhost | ok: Runtime: 0:00:00.186963
2026-03-12 10:38:11.349149 | 
2026-03-12 10:38:11.349209 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-03-12 10:38:11.365923 | controller | ok
2026-03-12 10:38:11.374210 | controller | included: /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-03-12 10:38:11.381062 | 
2026-03-12 10:38:11.381120 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-03-12 10:38:11.394080 | controller | skipping: Conditional result was False
2026-03-12 10:38:11.398800 | 
2026-03-12 10:38:11.398860 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-03-12 10:38:11.836234 | controller | changed
2026-03-12 10:38:11.840621 | 
2026-03-12 10:38:11.840679 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-03-12 10:38:12.090840 | controller | ok
2026-03-12 10:38:12.095395 | 
2026-03-12 10:38:12.095455 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-03-12 10:38:13.128227 | controller | changed
2026-03-12 10:38:13.132917 | 
2026-03-12 10:38:13.133004 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-03-12 10:38:14.134082 | controller | changed
2026-03-12 10:38:14.138767 | 
2026-03-12 10:38:14.138829 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-03-12 10:38:14.151563 | controller | skipping: Conditional result was False
2026-03-12 10:38:14.156337 | 
2026-03-12 10:38:14.156395 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-03-12 10:38:14.422523 | controller -> localhost | changed
2026-03-12 10:38:14.431403 | 
2026-03-12 10:38:14.431660 | TASK [add-build-sshkey : Add back temp key]
2026-03-12 10:38:14.637111 | controller -> localhost | Identity added: /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/a2b351dfb56646f4bf330d423e352d33_id_rsa (zuul-build-sshkey)
2026-03-12 10:38:14.637307 | controller -> localhost | ok: Runtime: 0:00:00.005963
2026-03-12 10:38:14.642543 | 
2026-03-12 10:38:14.642601 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-03-12 10:38:14.973195 | controller | ok
2026-03-12 10:38:14.977733 | 
2026-03-12 10:38:14.977796 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-03-12 10:38:15.000872 | controller | skipping: Conditional result was False
2026-03-12 10:38:15.010181 | 
2026-03-12 10:38:15.010242 | TASK [include_role : validate-host]
2026-03-12 10:38:15.026898 | controller | ok
2026-03-12 10:38:15.044027 | 
2026-03-12 10:38:15.044092 | TASK [validate-host : Define zuul_info_dir fact]
2026-03-12 10:38:15.061966 | controller | ok
2026-03-12 10:38:15.066342 | 
2026-03-12 10:38:15.066408 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-03-12 10:38:15.255087 | controller -> localhost | ok
2026-03-12 10:38:15.260458 | 
2026-03-12 10:38:15.260520 | TASK [validate-host : Collect information about the host]
2026-03-12 10:38:15.935053 | controller | ok
2026-03-12 10:38:15.942281 | 
2026-03-12 10:38:15.942337 | TASK [validate-host : Sanitize hostname]
2026-03-12 10:38:15.979645 | controller | ok
2026-03-12 10:38:15.984252 | 
2026-03-12 10:38:15.984353 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-03-12 10:38:16.321092 | controller -> localhost | changed
2026-03-12 10:38:16.326003 | 
2026-03-12 10:38:16.326069 | TASK [validate-host : Collect information about zuul worker]
2026-03-12 10:38:16.688048 | controller | ok
2026-03-12 10:38:16.692627 | 
2026-03-12 10:38:16.692700 | TASK [validate-host : Write out all zuul information for each host]
2026-03-12 10:38:17.039556 | controller -> localhost | changed
2026-03-12 10:38:17.049701 | 
2026-03-12 10:38:17.049767 | TASK [include_role : prepare-workspace-openshift]
2026-03-12 10:38:17.062973 | controller | skipping: Conditional result was False
2026-03-12 10:38:17.068060 | 
2026-03-12 10:38:17.068125 | TASK [include_role : remove-zuul-sshkey]
2026-03-12 10:38:17.082585 | controller | skipping: Conditional result was False
2026-03-12 10:38:17.088182 | 
2026-03-12 10:38:17.088247 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-03-12 10:38:17.334142 | controller | ok: "logs"
2026-03-12 10:38:17.334368 | controller | ok: All items complete
2026-03-12 10:38:17.334397 | 
2026-03-12 10:38:17.558088 | controller | ok: "artifacts"
2026-03-12 10:38:17.794906 | controller | ok: "docs"
2026-03-12 10:38:17.809282 | 
2026-03-12 10:38:17.809378 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-03-12 10:38:18.060831 | controller | changed: "logs"
2026-03-12 10:38:18.295543 | controller | changed: "artifacts"
2026-03-12 10:38:18.525707 | controller | changed: "docs"
2026-03-12 10:38:18.551516 | 
2026-03-12 10:38:18.551615 | PLAY RECAP
2026-03-12 10:38:18.551659 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-12 10:38:18.551685 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-12 10:38:18.551703 | 
2026-03-12 10:38:18.628194 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-12 10:38:18.628948 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-12 10:38:19.129683 | 
2026-03-12 10:38:19.129774 | PLAY [all]
2026-03-12 10:38:19.147216 | 
2026-03-12 10:38:19.147301 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-12 10:38:19.195891 | controller | ok
2026-03-12 10:38:19.200652 | 
2026-03-12 10:38:19.200729 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-12 10:38:19.564031 | controller | changed
2026-03-12 10:38:19.569441 | 
2026-03-12 10:38:19.569514 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-12 10:38:20.732686 | controller | changed
2026-03-12 10:38:20.741068 | 
2026-03-12 10:38:20.741133 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-03-12 10:38:21.139923 | controller | changed:
2026-03-12 10:38:21.140076 | controller | {
2026-03-12 10:38:21.140104 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-03-12 10:38:21.140146 | controller | }
2026-03-12 10:38:21.401688 | controller | changed:
2026-03-12 10:38:21.401740 | controller | {
2026-03-12 10:38:21.401765 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-03-12 10:38:21.401785 | controller | }
2026-03-12 10:38:21.671413 | controller | changed:
2026-03-12 10:38:21.671467 | controller | {
2026-03-12 10:38:21.671491 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2026-03-12 10:38:21.671510 | controller | }
2026-03-12 10:38:21.949837 | controller | changed:
2026-03-12 10:38:21.949913 | controller | {
2026-03-12 10:38:21.949951 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-03-12 10:38:21.949980 | controller | }
2026-03-12 10:38:22.220172 | controller | changed:
2026-03-12 10:38:22.220254 | controller | {
2026-03-12 10:38:22.220308 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-03-12 10:38:22.220333 | controller | }
2026-03-12 10:38:22.487107 | controller | changed:
2026-03-12 10:38:22.487214 | controller | {
2026-03-12 10:38:22.487249 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-03-12 10:38:22.487388 | controller | }
2026-03-12 10:38:22.759472 | controller | changed:
2026-03-12 10:38:22.759529 | controller | {
2026-03-12 10:38:22.759555 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2026-03-12 10:38:22.759576 | controller | }
2026-03-12 10:38:23.026221 | controller | changed:
2026-03-12 10:38:23.026326 | controller | {
2026-03-12 10:38:23.026354 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2026-03-12 10:38:23.026374 | controller | }
2026-03-12 10:38:23.297022 | controller | changed:
2026-03-12 10:38:23.297103 | controller | {
2026-03-12 10:38:23.297128 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-03-12 10:38:23.297148 | controller | }
2026-03-12 10:38:23.578757 | controller | changed:
2026-03-12 10:38:23.578838 | controller | {
2026-03-12 10:38:23.578862 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-03-12 10:38:23.578881 | controller | }
2026-03-12 10:38:23.833005 | controller | changed:
2026-03-12 10:38:23.833067 | controller | {
2026-03-12 10:38:23.833100 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-03-12 10:38:23.833126 | controller | }
2026-03-12 10:38:24.111105 | controller | changed:
2026-03-12 10:38:24.111532 | controller | {
2026-03-12 10:38:24.111569 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-03-12 10:38:24.111592 | controller | }
2026-03-12 10:38:24.384595 | controller | changed:
2026-03-12 10:38:24.384779 | controller | {
2026-03-12 10:38:24.384807 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-03-12 10:38:24.384828 | controller | }
2026-03-12 10:38:24.664095 | controller | changed:
2026-03-12 10:38:24.664200 | controller | {
2026-03-12 10:38:24.664226 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-03-12 10:38:24.664245 | controller | }
2026-03-12 10:38:24.930168 | controller | changed:
2026-03-12 10:38:24.930231 | controller | {
2026-03-12 10:38:24.930258 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-03-12 10:38:24.930304 | controller | }
2026-03-12 10:38:25.198992 | controller | changed:
2026-03-12 10:38:25.199043 | controller | {
2026-03-12 10:38:25.199067 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-03-12 10:38:25.199085 | controller | }
2026-03-12 10:38:25.465081 | controller | changed:
2026-03-12 10:38:25.465132 | controller | {
2026-03-12 10:38:25.465156 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2026-03-12 10:38:25.465175 | controller | }
2026-03-12 10:38:25.733994 | controller | changed:
2026-03-12 10:38:25.734077 | controller | {
2026-03-12 10:38:25.734104 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2026-03-12 10:38:25.734133 | controller | }
2026-03-12 10:38:26.004388 | controller | changed:
2026-03-12 10:38:26.004437 | controller | {
2026-03-12 10:38:26.004460 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-03-12 10:38:26.004477 | controller | }
2026-03-12 10:38:26.282205 | controller | changed:
2026-03-12 10:38:26.282371 | controller | {
2026-03-12 10:38:26.282404 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-03-12 10:38:26.282428 | controller | }
2026-03-12 10:38:26.554657 | controller | changed:
2026-03-12 10:38:26.554732 | controller | {
2026-03-12 10:38:26.554756 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-03-12 10:38:26.554774 | controller | }
2026-03-12 10:38:26.818992 | controller | changed:
2026-03-12 10:38:26.819096 | controller | {
2026-03-12 10:38:26.819124 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-03-12 10:38:26.819145 | controller | }
2026-03-12 10:38:27.090221 | controller | changed:
2026-03-12 10:38:27.090285 | controller | {
2026-03-12 10:38:27.090316 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2026-03-12 10:38:27.090338 | controller | }
2026-03-12 10:38:27.358988 | controller | changed:
2026-03-12 10:38:27.359040 | controller | {
2026-03-12 10:38:27.359065 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-03-12 10:38:27.359084 | controller | }
2026-03-12 10:38:27.635794 | controller | changed:
2026-03-12 10:38:27.635843 | controller | {
2026-03-12 10:38:27.635868 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-03-12 10:38:27.635886 | controller | }
2026-03-12 10:38:27.905912 | controller | changed:
2026-03-12 10:38:27.906003 | controller | {
2026-03-12 10:38:27.906029 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-03-12 10:38:27.906047 | controller | }
2026-03-12 10:38:27.930683 | 
2026-03-12 10:38:27.930775 | TASK [Set timezone to UTC]
2026-03-12 10:38:28.386417 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-03-12 10:38:28.392822 | 
2026-03-12 10:38:28.392901 | TASK [Create nodepool directory]
2026-03-12 10:38:28.661189 | controller | changed
2026-03-12 10:38:28.667415 | 
2026-03-12 10:38:28.667517 | TASK [Create nodepool sub_nodes file]
2026-03-12 10:38:29.587612 | controller | changed
2026-03-12 10:38:29.592437 | 
2026-03-12 10:38:29.592503 | TASK [Create nodepool sub_nodes_private file]
2026-03-12 10:38:30.534427 | controller | changed
2026-03-12 10:38:30.539990 | 
2026-03-12 10:38:30.540060 | LOOP [Populate nodepool sub_nodes file]
2026-03-12 10:38:30.571968 | 
2026-03-12 10:38:30.572113 | LOOP [Populate nodepool sub_nodes_private file]
2026-03-12 10:38:30.601996 | 
2026-03-12 10:38:30.602153 | TASK [Create nodepool primary file]
2026-03-12 10:38:30.626098 | controller | skipping: Conditional result was False
2026-03-12 10:38:30.632157 | 
2026-03-12 10:38:30.632236 | TASK [Create nodepool node_private for this node]
2026-03-12 10:38:31.663546 | controller | changed
2026-03-12 10:38:31.669340 | 
2026-03-12 10:38:31.669406 | LOOP [Copy ssh keys to nodepool directory]
2026-03-12 10:38:32.044089 | controller | ok: Item: id_rsa Runtime: 0:00:00.004899
2026-03-12 10:38:32.044293 | 
2026-03-12 10:38:32.269511 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005415
2026-03-12 10:38:32.277950 | 
2026-03-12 10:38:32.278053 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-03-12 10:38:33.319227 | controller | changed
2026-03-12 10:38:33.324387 | 
2026-03-12 10:38:33.324449 | TASK [Validate sudoers config after edits]
2026-03-12 10:38:33.593702 | controller | /etc/sudoers: parsed OK
2026-03-12 10:38:33.593820 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-03-12 10:38:33.593832 | controller | /etc/sudoers.d/zuul: parsed OK
2026-03-12 10:38:33.593838 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-03-12 10:38:33.848717 | controller | ok: Runtime: 0:00:00.005194
2026-03-12 10:38:33.853965 | 
2026-03-12 10:38:33.854022 | TASK [Show the environment passed in to job shell scripts]
2026-03-12 10:38:34.107170 | controller | SHELL=/bin/bash
2026-03-12 10:38:34.107219 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-03-12 10:38:34.107228 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-03-12 10:38:34.107236 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/39/3739/4e9aac59a57e68be0ca5eb6130e08e6e1a3f6723
2026-03-12 10:38:34.107242 | controller | PWD=/home/zuul
2026-03-12 10:38:34.107254 | controller | ZUUL_PIPELINE=github-check
2026-03-12 10:38:34.107300 | controller | LOGNAME=zuul
2026-03-12 10:38:34.107309 | controller | XDG_SESSION_TYPE=tty
2026-03-12 10:38:34.107314 | controller | _=/usr/bin/env
2026-03-12 10:38:34.107319 | controller | MOTD_SHOWN=pam
2026-03-12 10:38:34.107324 | controller | HOME=/home/zuul
2026-03-12 10:38:34.107329 | controller | LANG=en_US.UTF-8
2026-03-12 10:38:34.107334 | controller | SSH_CONNECTION=192.168.25.12 38298 192.168.25.5 22
2026-03-12 10:38:34.107339 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2026-03-12 10:38:34.107348 | controller | ZUUL_CHANGE_IDS=3739,4e9aac59a57e68be0ca5eb6130e08e6e1a3f6723
2026-03-12 10:38:34.107353 | controller | WORKSPACE=/home/zuul/workspace
2026-03-12 10:38:34.107358 | controller | XDG_SESSION_CLASS=user
2026-03-12 10:38:34.107363 | controller | SELINUX_ROLE_REQUESTED=
2026-03-12 10:38:34.107368 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-03-12 10:38:34.107373 | controller | USER=zuul
2026-03-12 10:38:34.107378 | controller | ZUUL_VOTING=True
2026-03-12 10:38:34.107383 | controller | BUILD_TIMEOUT=5400000
2026-03-12 10:38:34.107388 | controller | SELINUX_USE_CURRENT_RANGE=
2026-03-12 10:38:34.107393 | controller | SHLVL=1
2026-03-12 10:38:34.107398 | controller | ZUUL_PATCHSET=4e9aac59a57e68be0ca5eb6130e08e6e1a3f6723
2026-03-12 10:38:34.107403 | controller | XDG_SESSION_ID=1
2026-03-12 10:38:34.107408 | controller | ZUUL_BRANCH=main
2026-03-12 10:38:34.107413 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-03-12 10:38:34.107418 | controller | SSH_CLIENT=192.168.25.12 38298 22
2026-03-12 10:38:34.107423 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-03-12 10:38:34.107428 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-03-12 10:38:34.107433 | controller | which_declare=declare -f
2026-03-12 10:38:34.107440 | controller | PATH=/home/zuul/.crc/bin/oc:/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2026-03-12 10:38:34.107445 | controller | SELINUX_LEVEL_REQUESTED=
2026-03-12 10:38:34.107450 | controller | ZUUL_CHANGE=3739
2026-03-12 10:38:34.107454 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-03-12 10:38:34.107459 | controller | ZUUL_UUID=a2b351dfb56646f4bf330d423e352d33
2026-03-12 10:38:34.107464 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-03-12 10:38:34.107469 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-03-12 10:38:34.107475 | controller | }
2026-03-12 10:38:34.378741 | controller | ok: Runtime: 0:00:00.005858
2026-03-12 10:38:34.383544 | 
2026-03-12 10:38:34.383601 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-03-12 10:38:34.396704 | controller | skipping: Conditional result was False
2026-03-12 10:38:34.401506 | 
2026-03-12 10:38:34.401564 | TASK [Symlink /home/zuul-worker/workspace]
2026-03-12 10:38:34.923758 | controller | skipping: Conditional result was False
2026-03-12 10:38:34.947948 | 
2026-03-12 10:38:34.948039 | TASK [Ensure legacy workspace directory]
2026-03-12 10:38:35.198440 | controller | changed
2026-03-12 10:38:35.214990 | 
2026-03-12 10:38:35.215040 | PLAY RECAP
2026-03-12 10:38:35.215081 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-12 10:38:35.215102 | 
2026-03-12 10:38:35.282981 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-12 10:38:35.283661 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-12 10:38:35.734761 | 
2026-03-12 10:38:35.734852 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-03-12 10:38:35.753456 | 
2026-03-12 10:38:35.753527 | TASK [Create zuul-output directory]
2026-03-12 10:38:36.096664 | controller | changed
2026-03-12 10:38:36.101662 | 
2026-03-12 10:38:36.101737 | TASK [Slurp Zuul inventory test]
2026-03-12 10:38:36.358471 | controller -> localhost | ok
2026-03-12 10:38:36.363956 | 
2026-03-12 10:38:36.364019 | TASK [Save zuul inventory]
2026-03-12 10:38:37.459492 | controller | changed
2026-03-12 10:38:37.463853 | 
2026-03-12 10:38:37.463914 | TASK [Save zuul vars without the change_message]
2026-03-12 10:38:38.402822 | controller | changed
2026-03-12 10:38:38.418969 | 
2026-03-12 10:38:38.419017 | PLAY RECAP
2026-03-12 10:38:38.419055 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-12 10:38:38.419077 | 
2026-03-12 10:38:38.478537 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-12 10:38:38.479224 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-12 10:38:38.974018 | 
2026-03-12 10:38:38.974112 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-03-12 10:38:38.992513 | 
2026-03-12 10:38:38.992584 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-03-12 10:38:39.010726 | controller | ok
2026-03-12 10:38:39.026964 | 
2026-03-12 10:38:39.027048 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-12 10:38:39.050039 | controller | skipping: Conditional result was False
2026-03-12 10:38:39.055423 | 
2026-03-12 10:38:39.055488 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-12 10:38:39.408200 | controller | ok
2026-03-12 10:38:39.413458 | 
2026-03-12 10:38:39.413524 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-12 10:38:40.287583 | controller | ok
2026-03-12 10:38:40.296675 | 
2026-03-12 10:38:40.296741 | TASK [Prepare workspace]
2026-03-12 10:38:40.314990 | controller | ok
2026-03-12 10:38:40.331149 | 
2026-03-12 10:38:40.331217 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-03-12 10:38:40.654785 | controller | ok
2026-03-12 10:38:40.660347 | 
2026-03-12 10:38:40.660411 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-03-12 10:38:43.051964 | controller | Output suppressed because no_log was given
2026-03-12 10:38:43.061295 | 
2026-03-12 10:38:43.061363 | LOOP [Create zuul-output directory]
2026-03-12 10:38:43.339974 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-03-12 10:38:43.556541 | controller | ok: "/home/zuul/zuul-output/logs"
2026-03-12 10:38:43.568561 | 
2026-03-12 10:38:43.568660 | TASK [Install required packages]
2026-03-12 10:39:01.470655 | controller | ok: Nothing to do
2026-03-12 10:39:01.475642 | 
2026-03-12 10:39:01.475702 | TASK [Install venv]
2026-03-12 10:40:13.073350 | controller | changed
2026-03-12 10:40:13.100102 | 
2026-03-12 10:40:13.100179 | PLAY RECAP
2026-03-12 10:40:13.100225 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-03-12 10:40:13.100248 | 
2026-03-12 10:40:13.169980 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-12 10:40:13.170705 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-12 10:40:13.641474 | 
2026-03-12 10:40:13.641564 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-03-12 10:40:13.660099 | 
2026-03-12 10:40:13.660165 | TASK [Gather required facts]
2026-03-12 10:40:14.165618 | controller | ok
2026-03-12 10:40:14.170753 | 
2026-03-12 10:40:14.170826 | TASK [Load environment var if instructed to]
2026-03-12 10:40:14.194964 | controller | skipping: Conditional result was False
2026-03-12 10:40:14.199728 | 
2026-03-12 10:40:14.199789 | TASK [Ensure group_vars dir exists]
2026-03-12 10:40:14.543631 | controller | ok
2026-03-12 10:40:14.548846 | 
2026-03-12 10:40:14.548904 | TASK [Print related variables]
2026-03-12 10:40:14.577107 | controller | ok:
2026-03-12 10:40:14.577212 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-03-12 10:40:14.577238 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer
2026-03-12 10:40:14.581419 | 
2026-03-12 10:40:14.581496 | TASK [Run molecule]
2026-03-12 10:40:15.517453 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-03-12 10:40:15.845659 | controller | INFO     Running bm_redfish > prepare
2026-03-12 10:40:16.444149 | controller |
2026-03-12 10:40:16.444276 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-03-12 10:40:16.444356 | controller |
2026-03-12 10:40:16.444445 | controller | TASK [Create mock server directory] ********************************************
2026-03-12 10:40:16.444530 | controller | Thursday 12 March 2026  10:40:16 +0000 (0:00:00.024)       0:00:00.024 ********
2026-03-12 10:40:16.757264 | controller | changed: [instance]
2026-03-12 10:40:16.757353 | controller |
2026-03-12 10:40:16.757473 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-03-12 10:40:16.757591 | controller | Thursday 12 March 2026  10:40:16 +0000 (0:00:00.313)       0:00:00.338 ********
2026-03-12 10:40:17.111158 | controller | changed: [instance]
2026-03-12 10:40:17.111257 | controller |
2026-03-12 10:40:17.111360 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-03-12 10:40:17.111462 | controller | Thursday 12 March 2026  10:40:17 +0000 (0:00:00.354)       0:00:00.692 ********
2026-03-12 10:40:17.581059 | controller | changed: [instance]
2026-03-12 10:40:17.581102 | controller |
2026-03-12 10:40:17.581231 | controller | TASK [Start mock iDRAC server] *************************************************
2026-03-12 10:40:17.581331 | controller | Thursday 12 March 2026  10:40:17 +0000 (0:00:00.469)       0:00:01.161 ********
2026-03-12 10:40:17.755475 | controller | changed: [instance]
2026-03-12 10:40:17.755566 | controller |
2026-03-12 10:40:17.756105 | controller | TASK [Record mock server PID] **************************************************
2026-03-12 10:40:17.756238 | controller | Thursday 12 March 2026  10:40:17 +0000 (0:00:00.174)       0:00:01.336 ********
2026-03-12 10:40:17.941293 | controller | ok: [instance]
2026-03-12 10:40:17.941369 | controller |
2026-03-12 10:40:17.941464 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-03-12 10:40:17.941558 | controller | Thursday 12 March 2026  10:40:17 +0000 (0:00:00.185)       0:00:01.522 ********
2026-03-12 10:40:18.326815 | controller | ok: [instance]
2026-03-12 10:40:18.326856 | controller |
2026-03-12 10:40:18.327028 | controller | PLAY RECAP *********************************************************************
2026-03-12 10:40:18.327100 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-03-12 10:40:18.327216 | controller |
2026-03-12 10:40:18.327314 | controller | Thursday 12 March 2026  10:40:18 +0000 (0:00:00.385)       0:00:01.908 ********
2026-03-12 10:40:18.327395 | controller | ===============================================================================
2026-03-12 10:40:18.327502 | controller | Copy mock iDRAC server script ------------------------------------------- 0.47s
2026-03-12 10:40:18.327592 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.39s
2026-03-12 10:40:18.327688 | controller | Generate self-signed TLS certificate ------------------------------------ 0.35s
2026-03-12 10:40:18.327789 | controller | Create mock server directory -------------------------------------------- 0.31s
2026-03-12 10:40:18.327878 | controller | Record mock server PID -------------------------------------------------- 0.19s
2026-03-12 10:40:18.327968 | controller | Start mock iDRAC server ------------------------------------------------- 0.17s
2026-03-12 10:40:18.379437 | controller | INFO     Running bm_redfish > converge
2026-03-12 10:40:18.767199 | controller |
2026-03-12 10:40:18.767225 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-03-12 10:40:18.767421 | controller |
2026-03-12 10:40:18.767488 | controller | TASK [Test bm_power_off] *******************************************************
2026-03-12 10:40:18.767593 | controller | Thursday 12 March 2026  10:40:18 +0000 (0:00:00.043)       0:00:00.043 ********
2026-03-12 10:40:18.787548 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_power_off.yml for instance
2026-03-12 10:40:19.165959 | controller |
2026-03-12 10:40:19.165993 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-12 10:40:19.166002 | controller | Thursday 12 March 2026  10:40:18 +0000 (0:00:00.020)       0:00:00.064 ********
2026-03-12 10:40:19.166020 | controller | ok: [instance]
2026-03-12 10:40:19.166153 | controller |
2026-03-12 10:40:19.166185 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-12 10:40:19.166252 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.378)       0:00:00.442 ********
2026-03-12 10:40:19.192167 | controller |
2026-03-12 10:40:19.192196 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:19.192352 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.026)       0:00:00.469 ********
2026-03-12 10:40:19.462437 | controller | ok: [instance]
2026-03-12 10:40:19.477166 | controller |
2026-03-12 10:40:19.477193 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 10:40:19.477203 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.269)       0:00:00.739 ********
2026-03-12 10:40:19.477216 | controller | skipping: [instance]
2026-03-12 10:40:19.477226 | controller |
2026-03-12 10:40:19.477391 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 10:40:19.477453 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.015)       0:00:00.754 ********
2026-03-12 10:40:19.495260 | controller | skipping: [instance]
2026-03-12 10:40:19.495333 | controller |
2026-03-12 10:40:19.495484 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-03-12 10:40:19.495566 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.018)       0:00:00.772 ********
2026-03-12 10:40:19.763051 | controller | ok: [instance]
2026-03-12 10:40:19.763167 | controller |
2026-03-12 10:40:19.763186 | controller | TASK [Assert host is still Off] ************************************************
2026-03-12 10:40:19.763245 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.267)       0:00:01.040 ********
2026-03-12 10:40:19.781574 | controller | ok: [instance] => {
2026-03-12 10:40:19.781628 | controller |     "changed": false,
2026-03-12 10:40:19.782242 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:20.045484 | controller | }
2026-03-12 10:40:20.045502 | controller |
2026-03-12 10:40:20.045509 | controller | TASK [Reset mock to power On] **************************************************
2026-03-12 10:40:20.045515 | controller | Thursday 12 March 2026  10:40:19 +0000 (0:00:00.018)       0:00:01.059 ********
2026-03-12 10:40:20.045523 | controller | ok: [instance]
2026-03-12 10:40:20.068552 | controller |
2026-03-12 10:40:20.068574 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-12 10:40:20.068583 | controller | Thursday 12 March 2026  10:40:20 +0000 (0:00:00.263)       0:00:01.322 ********
2026-03-12 10:40:20.068594 | controller |
2026-03-12 10:40:20.336210 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:20.336244 | controller | Thursday 12 March 2026  10:40:20 +0000 (0:00:00.023)       0:00:01.345 ********
2026-03-12 10:40:20.336261 | controller | ok: [instance]
2026-03-12 10:40:20.336290 | controller |
2026-03-12 10:40:20.336466 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 10:40:20.602218 | controller | Thursday 12 March 2026  10:40:20 +0000 (0:00:00.267)       0:00:01.613 ********
2026-03-12 10:40:20.602271 | controller | ok: [instance]
2026-03-12 10:40:20.602314 | controller |
2026-03-12 10:40:20.602325 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 10:40:20.602354 | controller | Thursday 12 March 2026  10:40:20 +0000 (0:00:00.265)       0:00:01.879 ********
2026-03-12 10:40:20.882155 | controller | ok: [instance]
2026-03-12 10:40:21.144986 | controller |
2026-03-12 10:40:21.145011 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-03-12 10:40:21.145019 | controller | Thursday 12 March 2026  10:40:20 +0000 (0:00:00.279)       0:00:02.159 ********
2026-03-12 10:40:21.145028 | controller | ok: [instance]
2026-03-12 10:40:21.164283 | controller |
2026-03-12 10:40:21.164321 | controller | TASK [Assert host is now Off] **************************************************
2026-03-12 10:40:21.164331 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.262)       0:00:02.421 ********
2026-03-12 10:40:21.164344 | controller | ok: [instance] => {
2026-03-12 10:40:21.164375 | controller |     "changed": false,
2026-03-12 10:40:21.164383 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:21.164399 | controller | }
2026-03-12 10:40:21.164407 | controller |
2026-03-12 10:40:21.164417 | controller | TASK [Test bm_power_on] ********************************************************
2026-03-12 10:40:21.186247 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.019)       0:00:02.441 ********
2026-03-12 10:40:21.186276 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_power_on.yml for instance
2026-03-12 10:40:21.186365 | controller |
2026-03-12 10:40:21.186384 | controller | TASK [Reset mock to power On] **************************************************
2026-03-12 10:40:21.186397 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.022)       0:00:02.463 ********
2026-03-12 10:40:21.458721 | controller | ok: [instance]
2026-03-12 10:40:21.483110 | controller |
2026-03-12 10:40:21.483161 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-12 10:40:21.483174 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.272)       0:00:02.735 ********
2026-03-12 10:40:21.483188 | controller |
2026-03-12 10:40:21.762616 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:21.762635 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.024)       0:00:02.760 ********
2026-03-12 10:40:21.762645 | controller | ok: [instance]
2026-03-12 10:40:21.777837 | controller |
2026-03-12 10:40:21.777858 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 10:40:21.777868 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.279)       0:00:03.039 ********
2026-03-12 10:40:21.777879 | controller | skipping: [instance]
2026-03-12 10:40:22.054881 | controller |
2026-03-12 10:40:22.054910 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 10:40:22.054919 | controller | Thursday 12 March 2026  10:40:21 +0000 (0:00:00.015)       0:00:03.054 ********
2026-03-12 10:40:22.054929 | controller | ok: [instance]
2026-03-12 10:40:22.327861 | controller |
2026-03-12 10:40:22.327888 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-03-12 10:40:22.327897 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.276)       0:00:03.331 ********
2026-03-12 10:40:22.327908 | controller | ok: [instance]
2026-03-12 10:40:22.347189 | controller |
2026-03-12 10:40:22.347221 | controller | TASK [Assert host is still On] *************************************************
2026-03-12 10:40:22.347229 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.272)       0:00:03.604 ********
2026-03-12 10:40:22.347239 | controller | ok: [instance] => {
2026-03-12 10:40:22.347263 | controller |     "changed": false,
2026-03-12 10:40:22.347269 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:22.347276 | controller | }
2026-03-12 10:40:22.347285 | controller |
2026-03-12 10:40:22.347292 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-12 10:40:22.347357 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.019)       0:00:03.624 ********
2026-03-12 10:40:22.612607 | controller | ok: [instance]
2026-03-12 10:40:22.636248 | controller |
2026-03-12 10:40:22.636267 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-12 10:40:22.636280 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.265)       0:00:03.889 ********
2026-03-12 10:40:22.636291 | controller |
2026-03-12 10:40:22.636307 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:22.636314 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.023)       0:00:03.913 ********
2026-03-12 10:40:22.905837 | controller | ok: [instance]
2026-03-12 10:40:23.189020 | controller |
2026-03-12 10:40:23.189054 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 10:40:23.189062 | controller | Thursday 12 March 2026  10:40:22 +0000 (0:00:00.269)       0:00:04.182 ********
2026-03-12 10:40:23.189072 | controller | ok: [instance]
2026-03-12 10:40:23.459258 | controller |
2026-03-12 10:40:23.459294 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 10:40:23.459305 | controller | Thursday 12 March 2026  10:40:23 +0000 (0:00:00.283)       0:00:04.465 ********
2026-03-12 10:40:23.459318 | controller | ok: [instance]
2026-03-12 10:40:23.726875 | controller |
2026-03-12 10:40:23.726906 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-03-12 10:40:23.726914 | controller | Thursday 12 March 2026  10:40:23 +0000 (0:00:00.270)       0:00:04.736 ********
2026-03-12 10:40:23.726925 | controller | ok: [instance]
2026-03-12 10:40:23.745178 | controller |
2026-03-12 10:40:23.745206 | controller | TASK [Assert host is now On] ***************************************************
2026-03-12 10:40:23.745214 | controller | Thursday 12 March 2026  10:40:23 +0000 (0:00:00.267)       0:00:05.003 ********
2026-03-12 10:40:23.745223 | controller | ok: [instance] => {
2026-03-12 10:40:23.745246 | controller |     "changed": false,
2026-03-12 10:40:23.745251 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:23.745257 | controller | }
2026-03-12 10:40:23.745262 | controller |
2026-03-12 10:40:23.745269 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-03-12 10:40:23.745290 | controller | Thursday 12 March 2026  10:40:23 +0000 (0:00:00.018)       0:00:05.022 ********
2026-03-12 10:40:23.767227 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_check_usb_boot.yml for instance
2026-03-12 10:40:23.767309 | controller |
2026-03-12 10:40:23.767327 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-03-12 10:40:23.767339 | controller | Thursday 12 March 2026  10:40:23 +0000 (0:00:00.022)       0:00:05.044 ********
2026-03-12 10:40:24.035224 | controller | ok: [instance]
2026-03-12 10:40:24.035276 | controller |
2026-03-12 10:40:24.035287 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-03-12 10:40:24.035371 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.267)       0:00:05.312 ********
2026-03-12 10:40:24.058560 | controller |
2026-03-12 10:40:24.330183 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 10:40:24.330210 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.023)       0:00:05.335 ********
2026-03-12 10:40:24.330224 | controller | ok: [instance]
2026-03-12 10:40:24.330231 | controller |
2026-03-12 10:40:24.330236 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 10:40:24.330244 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.271)       0:00:05.607 ********
2026-03-12 10:40:24.359908 | controller | ok: [instance]
2026-03-12 10:40:24.387269 | controller |
2026-03-12 10:40:24.387298 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 10:40:24.387308 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.029)       0:00:05.636 ********
2026-03-12 10:40:24.387320 | controller | skipping: [instance]
2026-03-12 10:40:24.387350 | controller |
2026-03-12 10:40:24.387360 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-03-12 10:40:24.387475 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.027)       0:00:05.664 ********
2026-03-12 10:40:24.414968 | controller | ok: [instance] => {
2026-03-12 10:40:24.682532 | controller |     "changed": false,
2026-03-12 10:40:24.682563 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:24.682571 | controller | }
2026-03-12 10:40:24.682577 | controller |
2026-03-12 10:40:24.682583 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-12 10:40:24.682589 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.027)       0:00:05.691 ********
2026-03-12 10:40:24.682599 | controller | ok: [instance]
2026-03-12 10:40:24.706227 | controller |
2026-03-12 10:40:24.706260 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-03-12 10:40:24.706270 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.267)       0:00:05.959 ********
2026-03-12 10:40:24.706283 | controller |
2026-03-12 10:40:24.983049 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 10:40:24.983083 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.024)       0:00:05.983 ********
2026-03-12 10:40:24.983101 | controller | ok: [instance]
2026-03-12 10:40:25.012214 | controller |
2026-03-12 10:40:25.012247 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 10:40:25.012256 | controller | Thursday 12 March 2026  10:40:24 +0000 (0:00:00.276)       0:00:06.259 ********
2026-03-12 10:40:25.012272 | controller | ok: [instance]
2026-03-12 10:40:25.012421 | controller |
2026-03-12 10:40:25.012443 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 10:40:25.037491 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.029)       0:00:06.289 ********
2026-03-12 10:40:25.037520 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 10:40:25.042040 | controller |
2026-03-12 10:40:25.061628 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-03-12 10:40:25.061658 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.029)       0:00:06.319 ********
2026-03-12 10:40:25.061669 | controller | ok: [instance] => {
2026-03-12 10:40:25.089909 | controller |     "changed": false,
2026-03-12 10:40:25.089927 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:25.089935 | controller | }
2026-03-12 10:40:25.089941 | controller |
2026-03-12 10:40:25.089947 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-03-12 10:40:25.089952 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.019)       0:00:06.338 ********
2026-03-12 10:40:25.089961 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_ensure_usb_boot.yml for instance
2026-03-12 10:40:25.358063 | controller |
2026-03-12 10:40:25.358085 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-03-12 10:40:25.358093 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.028)       0:00:06.367 ********
2026-03-12 10:40:25.358102 | controller | ok: [instance]
2026-03-12 10:40:25.387773 | controller |
2026-03-12 10:40:25.387791 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-03-12 10:40:25.387799 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.267)       0:00:06.635 ********
2026-03-12 10:40:25.387808 | controller |
2026-03-12 10:40:25.408185 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 10:40:25.408203 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.029)       0:00:06.665 ********
2026-03-12 10:40:25.408214 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-12 10:40:25.675171 | controller |
2026-03-12 10:40:25.675197 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 10:40:25.675205 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.020)       0:00:06.685 ********
2026-03-12 10:40:25.675215 | controller | ok: [instance]
2026-03-12 10:40:25.706305 | controller |
2026-03-12 10:40:25.706351 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 10:40:25.706365 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.267)       0:00:06.952 ********
2026-03-12 10:40:25.706382 | controller | ok: [instance]
2026-03-12 10:40:25.734491 | controller |
2026-03-12 10:40:25.734520 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 10:40:25.734531 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.030)       0:00:06.983 ********
2026-03-12 10:40:25.734544 | controller | skipping: [instance]
2026-03-12 10:40:25.734858 | controller |
2026-03-12 10:40:25.734873 | controller | TASK [Query mock state] ********************************************************
2026-03-12 10:40:25.734883 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.028)       0:00:07.011 ********
2026-03-12 10:40:26.001646 | controller | ok: [instance]
2026-03-12 10:40:26.020248 | controller |
2026-03-12 10:40:26.020283 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-03-12 10:40:26.020294 | controller | Thursday 12 March 2026  10:40:25 +0000 (0:00:00.267)       0:00:07.278 ********
2026-03-12 10:40:26.020308 | controller | ok: [instance] => {
2026-03-12 10:40:26.293016 | controller |     "changed": false,
2026-03-12 10:40:26.293043 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:26.293052 | controller | }
2026-03-12 10:40:26.293059 | controller |
2026-03-12 10:40:26.293066 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-03-12 10:40:26.293072 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.018)       0:00:07.297 ********
2026-03-12 10:40:26.293090 | controller | ok: [instance]
2026-03-12 10:40:26.321238 | controller |
2026-03-12 10:40:26.321270 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-03-12 10:40:26.321280 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.272)       0:00:07.570 ********
2026-03-12 10:40:26.321290 | controller |
2026-03-12 10:40:26.342245 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 10:40:26.342281 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.028)       0:00:07.598 ********
2026-03-12 10:40:26.342297 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-12 10:40:26.342442 | controller |
2026-03-12 10:40:26.342473 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 10:40:26.342501 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.020)       0:00:07.619 ********
2026-03-12 10:40:26.617808 | controller | ok: [instance]
2026-03-12 10:40:26.647584 | controller |
2026-03-12 10:40:26.647605 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 10:40:26.647614 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.275)       0:00:07.894 ********
2026-03-12 10:40:26.647639 | controller | ok: [instance]
2026-03-12 10:40:26.673456 | controller |
2026-03-12 10:40:26.673474 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 10:40:26.673481 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.029)       0:00:07.924 ********
2026-03-12 10:40:26.673490 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 10:40:26.679102 | controller |
2026-03-12 10:40:26.706583 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-12 10:40:26.706603 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.030)       0:00:07.955 ********
2026-03-12 10:40:26.706614 | controller | skipping: [instance]
2026-03-12 10:40:26.976045 | controller |
2026-03-12 10:40:26.976070 | controller | TASK [reproducer : Set GenericUsbBoot BIOS attribute] **************************
2026-03-12 10:40:26.976077 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.028)       0:00:07.983 ********
2026-03-12 10:40:26.976087 | controller | ok: [instance]
2026-03-12 10:40:27.247988 | controller |
2026-03-12 10:40:27.248015 | controller | TASK [reproducer : Create BIOS config job to schedule the change] **************
2026-03-12 10:40:27.248022 | controller | Thursday 12 March 2026  10:40:26 +0000 (0:00:00.269)       0:00:08.253 ********
2026-03-12 10:40:27.248032 | controller | ok: [instance]
2026-03-12 10:40:27.269505 | controller |
2026-03-12 10:40:27.269521 | controller | TASK [reproducer : Power off before applying BIOS change] **********************
2026-03-12 10:40:27.269528 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.271)       0:00:08.525 ********
2026-03-12 10:40:27.269536 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-12 10:40:27.546226 | controller |
2026-03-12 10:40:27.546260 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:27.546268 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.021)       0:00:08.546 ********
2026-03-12 10:40:27.546278 | controller | ok: [instance]
2026-03-12 10:40:27.562590 | controller |
2026-03-12 10:40:27.562622 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 10:40:27.562631 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.276)       0:00:08.823 ********
2026-03-12 10:40:27.562642 | controller | skipping: [instance]
2026-03-12 10:40:27.580878 | controller |
2026-03-12 10:40:27.580896 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 10:40:27.580905 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.016)       0:00:08.839 ********
2026-03-12 10:40:27.580915 | controller | skipping: [instance]
2026-03-12 10:40:27.605063 | controller |
2026-03-12 10:40:27.605092 | controller | TASK [reproducer : Power on to apply BIOS config job during POST] **************
2026-03-12 10:40:27.605141 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.018)       0:00:08.857 ********
2026-03-12 10:40:27.605154 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_on.yml for instance
2026-03-12 10:40:27.875961 | controller |
2026-03-12 10:40:27.875990 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:27.875998 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.023)       0:00:08.881 ********
2026-03-12 10:40:27.876007 | controller | ok: [instance]
2026-03-12 10:40:28.156140 | controller |
2026-03-12 10:40:28.156171 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 10:40:28.156178 | controller | Thursday 12 March 2026  10:40:27 +0000 (0:00:00.271)       0:00:09.152 ********
2026-03-12 10:40:28.156188 | controller | ok: [instance]
2026-03-12 10:40:28.435086 | controller |
2026-03-12 10:40:28.435146 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 10:40:28.435159 | controller | Thursday 12 March 2026  10:40:28 +0000 (0:00:00.280)       0:00:09.433 ********
2026-03-12 10:40:28.435170 | controller | ok: [instance]
2026-03-12 10:40:28.461046 | controller |
2026-03-12 10:40:28.461065 | controller | TASK [reproducer : Power off after BIOS change applied] ************************
2026-03-12 10:40:28.461072 | controller | Thursday 12 March 2026  10:40:28 +0000 (0:00:00.278)       0:00:09.711 ********
2026-03-12 10:40:28.461082 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-12 10:40:28.739931 | controller |
2026-03-12 10:40:28.739962 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 10:40:28.739970 | controller | Thursday 12 March 2026  10:40:28 +0000 (0:00:00.026)       0:00:09.738 ********
2026-03-12 10:40:28.739984 | controller | ok: [instance]
2026-03-12 10:40:29.009870 | controller |
2026-03-12 10:40:29.009902 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 10:40:29.009910 | controller | Thursday 12 March 2026  10:40:28 +0000 (0:00:00.278)       0:00:10.016 ********
2026-03-12 10:40:29.009920 | controller | ok: [instance]
2026-03-12 10:40:29.292715 | controller |
2026-03-12 10:40:29.292737 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 10:40:29.292745 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.269)       0:00:10.286 ********
2026-03-12 10:40:29.292755 | controller | ok: [instance]
2026-03-12 10:40:29.558605 | controller |
2026-03-12 10:40:29.558625 | controller | TASK [Query mock state after auto-enable] **************************************
2026-03-12 10:40:29.558633 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.283)       0:00:10.569 ********
2026-03-12 10:40:29.558642 | controller | ok: [instance]
2026-03-12 10:40:29.579304 | controller |
2026-03-12 10:40:29.579350 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-03-12 10:40:29.579365 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.265)       0:00:10.835 ********
2026-03-12 10:40:29.579382 | controller | ok: [instance] => {
2026-03-12 10:40:29.850933 | controller |     "changed": false,
2026-03-12 10:40:29.850955 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:29.850963 | controller | }
2026-03-12 10:40:29.850969 | controller |
2026-03-12 10:40:29.850975 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-12 10:40:29.850980 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.020)       0:00:10.855 ********
2026-03-12 10:40:29.850989 | controller | ok: [instance]
2026-03-12 10:40:29.879518 | controller |
2026-03-12 10:40:29.879536 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-03-12 10:40:29.879544 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.272)       0:00:11.128 ********
2026-03-12 10:40:29.879553 | controller |
2026-03-12 10:40:29.899622 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 10:40:29.899638 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.028)       0:00:11.156 ********
2026-03-12 10:40:29.899647 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-12 10:40:30.168827 | controller |
2026-03-12 10:40:30.168848 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 10:40:30.168855 | controller | Thursday 12 March 2026  10:40:29 +0000 (0:00:00.020)       0:00:11.176 ********
2026-03-12 10:40:30.168864 | controller | ok: [instance]
2026-03-12 10:40:30.197995 | controller |
2026-03-12 10:40:30.198015 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 10:40:30.198022 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.269)       0:00:11.445 ********
2026-03-12 10:40:30.198032 | controller | ok: [instance]
2026-03-12 10:40:30.221907 | controller |
2026-03-12 10:40:30.221923 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 10:40:30.221930 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.029)       0:00:11.475 ********
2026-03-12 10:40:30.221938 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 10:40:30.226843 | controller |
2026-03-12 10:40:30.251282 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-12 10:40:30.251296 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.028)       0:00:11.504 ********
2026-03-12 10:40:30.251305 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443. Set cifmw_bm_agent_enable_usb_boot: true in vars.yaml to allow this playbook to enable it automatically (requires a reboot cycle)."}
2026-03-12 10:40:30.256130 | controller |
2026-03-12 10:40:30.276302 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-03-12 10:40:30.276340 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.029)       0:00:11.533 ********
2026-03-12 10:40:30.276355 | controller | ok: [instance] => {
2026-03-12 10:40:30.276387 | controller |     "changed": false,
2026-03-12 10:40:30.276395 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:30.276404 | controller | }
2026-03-12 10:40:30.276739 | controller |
2026-03-12 10:40:30.304923 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-03-12 10:40:30.304939 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.020)       0:00:11.553 ********
2026-03-12 10:40:30.304949 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_eject_vmedia.yml for instance
2026-03-12 10:40:30.571420 | controller |
2026-03-12 10:40:30.571439 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 10:40:30.571446 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.028)       0:00:11.582 ********
2026-03-12 10:40:30.571456 | controller | ok: [instance]
2026-03-12 10:40:30.595639 | controller |
2026-03-12 10:40:30.595668 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-03-12 10:40:30.595680 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.266)       0:00:11.848 ********
2026-03-12 10:40:30.595695 | controller |
2026-03-12 10:40:30.863523 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-12 10:40:30.863565 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.024)       0:00:11.872 ********
2026-03-12 10:40:30.863578 | controller | ok: [instance]
2026-03-12 10:40:35.887721 | controller |
2026-03-12 10:40:35.887750 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-12 10:40:35.887757 | controller | Thursday 12 March 2026  10:40:30 +0000 (0:00:00.267)       0:00:12.140 ********
2026-03-12 10:40:35.887766 | controller | Pausing for 5 seconds
2026-03-12 10:40:36.162221 | controller | ok: [instance]
2026-03-12 10:40:36.162259 | controller |
2026-03-12 10:40:36.162270 | controller | TASK [Query mock state after eject] ********************************************
2026-03-12 10:40:36.162278 | controller | Thursday 12 March 2026  10:40:35 +0000 (0:00:05.024)       0:00:17.164 ********
2026-03-12 10:40:36.162293 | controller | ok: [instance]
2026-03-12 10:40:36.189739 | controller |
2026-03-12 10:40:36.189770 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-03-12 10:40:36.189779 | controller | Thursday 12 March 2026  10:40:36 +0000 (0:00:00.274)       0:00:17.439 ********
2026-03-12 10:40:36.189795 | controller | ok: [instance] => {
2026-03-12 10:40:36.457201 | controller |     "changed": false,
2026-03-12 10:40:36.457237 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:36.457245 | controller | }
2026-03-12 10:40:36.457251 | controller |
2026-03-12 10:40:36.457257 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-03-12 10:40:36.457263 | controller | Thursday 12 March 2026  10:40:36 +0000 (0:00:00.027)       0:00:17.466 ********
2026-03-12 10:40:36.457274 | controller | ok: [instance]
2026-03-12 10:40:36.481017 | controller |
2026-03-12 10:40:36.481048 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-03-12 10:40:36.481056 | controller | Thursday 12 March 2026  10:40:36 +0000 (0:00:00.267)       0:00:17.734 ********
2026-03-12 10:40:36.481067 | controller |
2026-03-12 10:40:36.754013 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-12 10:40:36.754045 | controller | Thursday 12 March 2026  10:40:36 +0000 (0:00:00.023)       0:00:17.758 ********
2026-03-12 10:40:36.754057 | controller | ok: [instance]
2026-03-12 10:40:41.775080 | controller |
2026-03-12 10:40:41.775135 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-12 10:40:41.775146 | controller | Thursday 12 March 2026  10:40:36 +0000 (0:00:00.272)       0:00:18.030 ********
2026-03-12 10:40:41.775157 | controller | Pausing for 5 seconds
2026-03-12 10:40:42.047058 | controller | ok: [instance]
2026-03-12 10:40:42.047084 | controller |
2026-03-12 10:40:42.047092 | controller | TASK [Query mock state] ********************************************************
2026-03-12 10:40:42.047098 | controller | Thursday 12 March 2026  10:40:41 +0000 (0:00:05.020)       0:00:23.051 ********
2026-03-12 10:40:42.047108 | controller | ok: [instance]
2026-03-12 10:40:42.074283 | controller |
2026-03-12 10:40:42.074330 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-03-12 10:40:42.074344 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.272)       0:00:23.324 ********
2026-03-12 10:40:42.074361 | controller | ok: [instance] => {
2026-03-12 10:40:42.074428 | controller |     "changed": false,
2026-03-12 10:40:42.074445 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:42.074693 | controller | }
2026-03-12 10:40:42.074713 | controller |
2026-03-12 10:40:42.119277 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-03-12 10:40:42.119320 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.027)       0:00:23.351 ********
2026-03-12 10:40:42.119336 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/tasks/test_discover_vmedia.yml for instance
2026-03-12 10:40:42.119369 | controller |
2026-03-12 10:40:42.119381 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 10:40:42.119424 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.045)       0:00:23.396 ********
2026-03-12 10:40:42.397041 | controller | ok: [instance]
2026-03-12 10:40:42.430483 | controller |
2026-03-12 10:40:42.430508 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-03-12 10:40:42.430518 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.277)       0:00:23.673 ********
2026-03-12 10:40:42.430529 | controller |
2026-03-12 10:40:42.708251 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 10:40:42.708283 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.033)       0:00:23.707 ********
2026-03-12 10:40:42.708297 | controller | ok: [instance]
2026-03-12 10:40:44.009283 | controller |
2026-03-12 10:40:44.009320 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 10:40:44.009330 | controller | Thursday 12 March 2026  10:40:42 +0000 (0:00:00.277)       0:00:23.985 ********
2026-03-12 10:40:44.009343 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 10:40:44.045284 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 10:40:44.045319 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 10:40:44.045328 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 10:40:44.045335 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 10:40:44.045342 | controller |
2026-03-12 10:40:44.045350 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 10:40:44.045379 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:01.300)       0:00:25.285 ********
2026-03-12 10:40:44.045398 | controller | ok: [instance]
2026-03-12 10:40:44.065240 | controller |
2026-03-12 10:40:44.065279 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 10:40:44.065286 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.036)       0:00:25.322 ********
2026-03-12 10:40:44.065297 | controller | skipping: [instance]
2026-03-12 10:40:44.127088 | controller |
2026-03-12 10:40:44.127109 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-12 10:40:44.127139 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.019)       0:00:25.342 ********
2026-03-12 10:40:44.127151 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-12 10:40:44.146672 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-12 10:40:44.146695 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-03-12 10:40:44.146705 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-12 10:40:44.146713 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-12 10:40:44.146721 | controller |
2026-03-12 10:40:44.146728 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-12 10:40:44.146736 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.061)       0:00:25.403 ********
2026-03-12 10:40:44.146747 | controller | skipping: [instance]
2026-03-12 10:40:44.166745 | controller |
2026-03-12 10:40:44.166765 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-12 10:40:44.166773 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.019)       0:00:25.423 ********
2026-03-12 10:40:44.166783 | controller | ok: [instance] => {
2026-03-12 10:40:44.434600 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-12 10:40:44.434622 | controller | }
2026-03-12 10:40:44.434630 | controller |
2026-03-12 10:40:44.434636 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-12 10:40:44.434641 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.020)       0:00:25.443 ********
2026-03-12 10:40:44.434650 | controller | ok: [instance]
2026-03-12 10:40:54.464321 | controller |
2026-03-12 10:40:54.464367 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-12 10:40:54.464377 | controller | Thursday 12 March 2026  10:40:44 +0000 (0:00:00.268)       0:00:25.711 ********
2026-03-12 10:40:54.464391 | controller | Pausing for 10 seconds
2026-03-12 10:40:54.464443 | controller | ok: [instance]
2026-03-12 10:40:54.464452 | controller |
2026-03-12 10:40:54.464461 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-12 10:40:54.750325 | controller | Thursday 12 March 2026  10:40:54 +0000 (0:00:10.029)       0:00:35.741 ********
2026-03-12 10:40:54.750379 | controller | ok: [instance]
2026-03-12 10:40:54.750421 | controller |
2026-03-12 10:40:54.750436 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-12 10:40:54.750538 | controller | Thursday 12 March 2026  10:40:54 +0000 (0:00:00.286)       0:00:36.027 ********
2026-03-12 10:40:55.032068 | controller | ok: [instance]
2026-03-12 10:40:55.055219 | controller |
2026-03-12 10:40:55.055250 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-12 10:40:55.055258 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.281)       0:00:36.309 ********
2026-03-12 10:40:55.055276 | controller | ok: [instance] => {
2026-03-12 10:40:55.055300 | controller |     "changed": false,
2026-03-12 10:40:55.055315 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:55.055332 | controller | }
2026-03-12 10:40:55.055604 | controller |
2026-03-12 10:40:55.328812 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-12 10:40:55.328845 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.023)       0:00:36.332 ********
2026-03-12 10:40:55.328857 | controller | ok: [instance]
2026-03-12 10:40:55.363305 | controller |
2026-03-12 10:40:55.363354 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-12 10:40:55.363380 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.273)       0:00:36.605 ********
2026-03-12 10:40:55.363398 | controller | ok: [instance] => {
2026-03-12 10:40:55.397253 | controller |     "changed": false,
2026-03-12 10:40:55.397290 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:55.397298 | controller | }
2026-03-12 10:40:55.397305 | controller |
2026-03-12 10:40:55.397311 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-03-12 10:40:55.397317 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.034)       0:00:36.640 ********
2026-03-12 10:40:55.397327 | controller | ok: [instance] => {
2026-03-12 10:40:55.397354 | controller |     "changed": false,
2026-03-12 10:40:55.397360 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:55.397366 | controller | }
2026-03-12 10:40:55.397373 | controller |
2026-03-12 10:40:55.397529 | controller | TASK [Query mock state after discover] *****************************************
2026-03-12 10:40:55.659480 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.034)       0:00:36.674 ********
2026-03-12 10:40:55.659511 | controller | ok: [instance]
2026-03-12 10:40:55.683299 | controller |
2026-03-12 10:40:55.683338 | controller | TASK [Assert boot override was set] ********************************************
2026-03-12 10:40:55.683353 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.262)       0:00:36.936 ********
2026-03-12 10:40:55.683370 | controller | ok: [instance] => {
2026-03-12 10:40:55.683381 | controller |     "changed": false,
2026-03-12 10:40:55.683392 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:55.683402 | controller | }
2026-03-12 10:40:55.683412 | controller |
2026-03-12 10:40:55.683422 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 10:40:55.683434 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.023)       0:00:36.960 ********
2026-03-12 10:40:55.954148 | controller | ok: [instance]
2026-03-12 10:40:55.983860 | controller |
2026-03-12 10:40:55.983881 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-03-12 10:40:55.983889 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.270)       0:00:37.231 ********
2026-03-12 10:40:55.983898 | controller |
2026-03-12 10:40:56.245157 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 10:40:56.245183 | controller | Thursday 12 March 2026  10:40:55 +0000 (0:00:00.029)       0:00:37.261 ********
2026-03-12 10:40:56.245203 | controller | ok: [instance]
2026-03-12 10:40:57.548137 | controller |
2026-03-12 10:40:57.548175 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 10:40:57.548184 | controller | Thursday 12 March 2026  10:40:56 +0000 (0:00:00.260)       0:00:37.522 ********
2026-03-12 10:40:57.548194 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 10:40:57.583080 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 10:40:57.583107 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 10:40:57.583158 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 10:40:57.583182 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 10:40:57.583190 | controller |
2026-03-12 10:40:57.583197 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 10:40:57.583204 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:01.302)       0:00:38.824 ********
2026-03-12 10:40:57.583216 | controller | ok: [instance]
2026-03-12 10:40:57.622342 | controller |
2026-03-12 10:40:57.622392 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 10:40:57.622407 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.035)       0:00:38.860 ********
2026-03-12 10:40:57.622424 | controller | ok: [instance] => {
2026-03-12 10:40:57.676320 | controller |     "changed": false,
2026-03-12 10:40:57.676368 | controller |     "msg": "All assertions passed"
2026-03-12 10:40:57.676382 | controller | }
2026-03-12 10:40:57.676392 | controller |
2026-03-12 10:40:57.676403 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-12 10:40:57.676413 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.038)       0:00:38.898 ********
2026-03-12 10:40:57.676430 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-12 10:40:57.676474 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-12 10:40:57.676485 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-03-12 10:40:57.676509 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-12 10:40:57.676836 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-12 10:40:57.676858 | controller | skipping: [instance]
2026-03-12 10:40:57.695892 | controller |
2026-03-12 10:40:57.695915 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-12 10:40:57.695924 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.054)       0:00:38.953 ********
2026-03-12 10:40:57.695935 | controller | skipping: [instance]
2026-03-12 10:40:57.713800 | controller |
2026-03-12 10:40:57.713822 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-12 10:40:57.713832 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.019)       0:00:38.972 ********
2026-03-12 10:40:57.713843 | controller | ok: [instance] => {
2026-03-12 10:40:57.714021 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-12 10:40:57.714223 | controller | }
2026-03-12 10:40:57.714379 | controller |
2026-03-12 10:40:57.714534 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-12 10:40:57.714667 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.018)       0:00:38.991 ********
2026-03-12 10:40:57.983982 | controller | ok: [instance]
2026-03-12 10:41:08.009358 | controller |
2026-03-12 10:41:08.009404 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-12 10:41:08.009414 | controller | Thursday 12 March 2026  10:40:57 +0000 (0:00:00.269)       0:00:39.261 ********
2026-03-12 10:41:08.009426 | controller | Pausing for 10 seconds
2026-03-12 10:41:08.292703 | controller | ok: [instance]
2026-03-12 10:41:08.292733 | controller |
2026-03-12 10:41:08.292741 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-12 10:41:08.292747 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:10.024)       0:00:49.285 ********
2026-03-12 10:41:08.292757 | controller | ok: [instance]
2026-03-12 10:41:08.566185 | controller |
2026-03-12 10:41:08.566221 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-12 10:41:08.566231 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:00.283)       0:00:49.569 ********
2026-03-12 10:41:08.566244 | controller | ok: [instance]
2026-03-12 10:41:08.588279 | controller |
2026-03-12 10:41:08.588329 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-12 10:41:08.588341 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:00.273)       0:00:49.843 ********
2026-03-12 10:41:08.588356 | controller | ok: [instance] => {
2026-03-12 10:41:08.588390 | controller |     "changed": false,
2026-03-12 10:41:08.588404 | controller |     "msg": "All assertions passed"
2026-03-12 10:41:08.588412 | controller | }
2026-03-12 10:41:08.588420 | controller |
2026-03-12 10:41:08.588435 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-12 10:41:08.588519 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:00.022)       0:00:49.865 ********
2026-03-12 10:41:08.857931 | controller | ok: [instance]
2026-03-12 10:41:08.857980 | controller |
2026-03-12 10:41:08.857991 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-12 10:41:08.858101 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:00.269)       0:00:50.135 ********
2026-03-12 10:41:08.891583 | controller | ok: [instance] => {
2026-03-12 10:41:08.891655 | controller |     "changed": false,
2026-03-12 10:41:08.891668 | controller |     "msg": "All assertions passed"
2026-03-12 10:41:08.891678 | controller | }
2026-03-12 10:41:08.891691 | controller |
2026-03-12 10:41:08.891725 | controller | TASK [Query mock state] ********************************************************
2026-03-12 10:41:08.891861 | controller | Thursday 12 March 2026  10:41:08 +0000 (0:00:00.033)       0:00:50.168 ********
2026-03-12 10:41:09.156672 | controller | ok: [instance]
2026-03-12 10:41:09.177101 | controller |
2026-03-12 10:41:09.177142 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-03-12 10:41:09.177152 | controller | Thursday 12 March 2026  10:41:09 +0000 (0:00:00.264)       0:00:50.433 ********
2026-03-12 10:41:09.177163 | controller | ok: [instance] => {
2026-03-12 10:41:09.447000 | controller |     "changed": false,
2026-03-12 10:41:09.447038 | controller |     "msg": "All assertions passed"
2026-03-12 10:41:09.447046 | controller | }
2026-03-12 10:41:09.447052 | controller |
2026-03-12 10:41:09.447057 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 10:41:09.447063 | controller | Thursday 12 March 2026  10:41:09 +0000 (0:00:00.020)       0:00:50.453 ********
2026-03-12 10:41:09.447073 | controller | ok: [instance]
2026-03-12 10:41:09.477444 | controller |
2026-03-12 10:41:09.477466 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-03-12 10:41:09.477475 | controller | Thursday 12 March 2026  10:41:09 +0000 (0:00:00.270)       0:00:50.724 ********
2026-03-12 10:41:09.477486 | controller |
2026-03-12 10:41:09.748053 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 10:41:09.748085 | controller | Thursday 12 March 2026  10:41:09 +0000 (0:00:00.030)       0:00:50.754 ********
2026-03-12 10:41:09.748097 | controller | ok: [instance]
2026-03-12 10:41:11.030244 | controller |
2026-03-12 10:41:11.030279 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 10:41:11.030289 | controller | Thursday 12 March 2026  10:41:09 +0000 (0:00:00.270)       0:00:51.025 ********
2026-03-12 10:41:11.030301 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 10:41:11.030341 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 10:41:11.030350 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 10:41:11.030359 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 10:41:11.030384 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 10:41:11.030676 | controller |
2026-03-12 10:41:11.066070 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 10:41:11.066096 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:01.282)       0:00:52.307 ********
2026-03-12 10:41:11.066107 | controller | ok: [instance]
2026-03-12 10:41:11.100236 | controller |
2026-03-12 10:41:11.100263 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 10:41:11.100273 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:00.036)       0:00:52.343 ********
2026-03-12 10:41:11.100284 | controller | fatal: [instance]: FAILED! => {
2026-03-12 10:41:11.100328 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-03-12 10:41:11.100337 | controller |     "changed": false,
2026-03-12 10:41:11.100344 | controller |     "evaluated_to": false,
2026-03-12 10:41:11.100354 | controller |     "msg": "cifmw_bm_agent_vmedia_uefi_path 'PciRoot(0x0)/INVALID/PATH' is not listed in UEFI boot options. Available paths: PXE Device 1: Embedded NIC 1 Port 1 Partition 1 -> VenHw(3A191845-5F86-4E78-8FCE-C4CFF59F9DAA), Virtual Floppy Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x1), Virtual Optical Drive -> PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0), Integrated RAID Controller 1: Red Hat Enterprise Linux -> HD(2,GPT,FF726BC2-263F-EE4A-BAE7-7CACE574EBD8,0x1000,0x3F800)/\\EFI\\redhat\\shimx64.efi, Generic USB Boot -> VenHw(0C8CB6CC-13AE-45F4-BBCD-6A25E98AC250)"
2026-03-12 10:41:11.100364 | controller | }
2026-03-12 10:41:11.104758 | controller |
2026-03-12 10:41:11.143221 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-03-12 10:41:11.143246 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:00.038)       0:00:52.382 ********
2026-03-12 10:41:11.143259 | controller | ok: [instance] => {
2026-03-12 10:41:11.143289 | controller |     "changed": false,
2026-03-12 10:41:11.143297 | controller |     "msg": "All assertions passed"
2026-03-12 10:41:11.143304 | controller | }
2026-03-12 10:41:11.143311 | controller |
2026-03-12 10:41:11.143328 | controller | PLAY RECAP *********************************************************************
2026-03-12 10:41:11.143335 | controller | instance                   : ok=110  changed=0    unreachable=0    failed=0    skipped=12   rescued=5    ignored=0
2026-03-12 10:41:11.143344 | controller |
2026-03-12 10:41:11.143378 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:00.037)       0:00:52.419 ********
2026-03-12 10:41:11.145078 | controller | ===============================================================================
2026-03-12 10:41:11.196299 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-12 10:41:11.196334 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.02s
2026-03-12 10:41:11.196342 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.02s
2026-03-12 10:41:11.196348 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.02s
2026-03-12 10:41:11.196353 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.30s
2026-03-12 10:41:11.196357 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.30s
2026-03-12 10:41:11.196362 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.28s
2026-03-12 10:41:11.196367 | controller | Reset mock to power Off ------------------------------------------------- 0.38s
2026-03-12 10:41:11.196372 | controller | reproducer : Set one-time boot from Virtual Optical Drive --------------- 0.29s
2026-03-12 10:41:11.196377 | controller | reproducer : Set one-time boot from Virtual Optical Drive --------------- 0.28s
2026-03-12 10:41:11.196386 | controller | reproducer : Wait for host to power off --------------------------------- 0.28s
2026-03-12 10:41:11.196391 | controller | reproducer : Power on bare metal host ----------------------------------- 0.28s
2026-03-12 10:41:11.196396 | controller | reproducer : Verify boot override was applied --------------------------- 0.28s
2026-03-12 10:41:11.196401 | controller | reproducer : Power on bare metal host ----------------------------------- 0.28s
2026-03-12 10:41:11.196406 | controller | reproducer : Wait for host to power off --------------------------------- 0.28s
2026-03-12 10:41:11.196410 | controller | reproducer : Query current power state ---------------------------------- 0.28s
2026-03-12 10:41:11.196415 | controller | reproducer : Wait for host POST to complete ----------------------------- 0.28s
2026-03-12 10:41:11.196420 | controller | reproducer : Query current power state ---------------------------------- 0.28s
2026-03-12 10:41:11.196425 | controller | reproducer : Fetch UEFI boot option IDs --------------------------------- 0.28s
2026-03-12 10:41:11.196430 | controller | Reset mock with VirtualMedia inserted ----------------------------------- 0.28s
2026-03-12 10:41:11.196438 | controller | INFO     Running bm_redfish > cleanup
2026-03-12 10:41:11.585618 | controller |
2026-03-12 10:41:11.585840 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-12 10:41:11.585989 | controller |
2026-03-12 10:41:11.586142 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-12 10:41:11.586292 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:00.023)       0:00:00.023 ********
2026-03-12 10:41:11.863007 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.014788", "end": "2026-03-12 10:41:11.841171", "msg": "non-zero return code", "rc": -15, "start": "2026-03-12 10:41:11.826383", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-12 10:41:11.864960 | controller |
2026-03-12 10:41:11.907215 | controller | PLAY RECAP *********************************************************************
2026-03-12 10:41:11.907264 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-12 10:41:11.907273 | controller |
2026-03-12 10:41:11.907281 | controller | Thursday 12 March 2026  10:41:11 +0000 (0:00:00.279)       0:00:00.302 ********
2026-03-12 10:41:11.907288 | controller | ===============================================================================
2026-03-12 10:41:11.907295 | controller | Stop mock iDRAC server -------------------------------------------------- 0.28s
2026-03-12 10:41:11.907309 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/reproducer/bm_redfish/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/cleanup.yml']
2026-03-12 10:41:11.907357 | controller | WARNING  An error occurred during the test sequence action: 'cleanup'. Cleaning up.
2026-03-12 10:41:11.916111 | controller | INFO     Running bm_redfish > cleanup
2026-03-12 10:41:12.315823 | controller |
2026-03-12 10:41:12.315949 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-12 10:41:12.316060 | controller |
2026-03-12 10:41:12.316198 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-12 10:41:12.316332 | controller | Thursday 12 March 2026  10:41:12 +0000 (0:00:00.023)       0:00:00.023 ********
2026-03-12 10:41:12.596382 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.012837", "end": "2026-03-12 10:41:12.575031", "msg": "non-zero return code", "rc": -15, "start": "2026-03-12 10:41:12.562194", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-12 10:41:12.598158 | controller |
2026-03-12 10:41:12.647145 | controller | PLAY RECAP *********************************************************************
2026-03-12 10:41:12.647167 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-12 10:41:12.647175 | controller |
2026-03-12 10:41:12.647181 | controller | Thursday 12 March 2026  10:41:12 +0000 (0:00:00.282)       0:00:00.305 ********
2026-03-12 10:41:12.647186 | controller | ===============================================================================
2026-03-12 10:41:12.647192 | controller | Stop mock iDRAC server -------------------------------------------------- 0.28s
2026-03-12 10:41:12.647201 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/reproducer/bm_redfish/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/molecule/bm_redfish/cleanup.yml']
2026-03-12 10:41:12.695390 | controller | INFO     Writing /tmp/report.html report.
2026-03-12 10:41:13.175771 | controller | ERROR
2026-03-12 10:41:13.175931 | controller | {
2026-03-12 10:41:13.175968 | controller |   "delta": "0:00:57.771458",
2026-03-12 10:41:13.175991 | controller |   "end": "2026-03-12 10:41:12.695903",
2026-03-12 10:41:13.176008 | controller |   "msg": "non-zero return code",
2026-03-12 10:41:13.176023 | controller |   "rc": 2,
2026-03-12 10:41:13.176038 | controller |   "start": "2026-03-12 10:40:14.924445"
2026-03-12 10:41:13.176053 | controller | }
failure
2026-03-12 10:41:13.224928 | 
2026-03-12 10:41:13.224979 | PLAY RECAP
2026-03-12 10:41:13.225020 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2026-03-12 10:41:13.225042 | 
2026-03-12 10:41:13.286010 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-12 10:41:13.287046 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-12 10:41:13.769588 | 
2026-03-12 10:41:13.769689 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-03-12 10:41:13.788482 | 
2026-03-12 10:41:13.788549 | TASK [Filter out host if needed]
2026-03-12 10:41:13.796180 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-03-12 10:41:13.800252 | 
2026-03-12 10:41:13.800338 | TASK [Ensure file is present]
2026-03-12 10:41:14.142821 | controller | ok
2026-03-12 10:41:14.149006 | 
2026-03-12 10:41:14.149065 | TASK [Manage molecule report file]
2026-03-12 10:41:14.673258 | controller | changed
2026-03-12 10:41:14.678256 | 
2026-03-12 10:41:14.678335 | TASK [Check if we get ci-framework-data basedir]
2026-03-12 10:41:14.919495 | controller | ok
2026-03-12 10:41:14.924000 | 
2026-03-12 10:41:14.924056 | TASK [Create ci-framework-data log directory for zuul]
2026-03-12 10:41:15.266962 | controller | changed
2026-03-12 10:41:15.271937 | 
2026-03-12 10:41:15.272003 | TASK [Copy ci-framework interesting files]
2026-03-12 10:41:15.520136 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-03-12 10:41:15.798231 | controller | changed
2026-03-12 10:41:15.802748 | 
2026-03-12 10:41:15.802808 | TASK [Get SELinux listing]
2026-03-12 10:41:16.327346 | controller | changed
2026-03-12 10:41:16.332419 | 
2026-03-12 10:41:16.332481 | TASK [Generate log index]
2026-03-12 10:41:17.369896 | controller | changed
2026-03-12 10:41:17.374781 | 
2026-03-12 10:41:17.374848 | TASK [Get some env related data]
2026-03-12 10:41:18.004891 | controller | /home/zuul/.local/bin/ansible
2026-03-12 10:41:18.913222 | controller | changed
2026-03-12 10:41:18.918098 | 
2026-03-12 10:41:18.918157 | TASK [Generate list of logs to collect in home directory]
2026-03-12 10:41:19.252099 | controller | ok: All paths examined
2026-03-12 10:41:19.281931 | 
2026-03-12 10:41:19.282010 | LOOP [Copy logs from home directory]
2026-03-12 10:41:19.797623 | controller | changed:
2026-03-12 10:41:19.797844 | controller | {
2026-03-12 10:41:19.797876 | controller |   "atime": 1772005405.932821,
2026-03-12 10:41:19.797897 | controller |   "ctime": 1772006396.9238591,
2026-03-12 10:41:19.797927 | controller |   "dev": 64513,
2026-03-12 10:41:19.797952 | controller |   "gid": 1000,
2026-03-12 10:41:19.797971 | controller |   "gr_name": "zuul",
2026-03-12 10:41:19.797990 | controller |   "inode": 2773,
2026-03-12 10:41:19.798007 | controller |   "isblk": false,
2026-03-12 10:41:19.798023 | controller |   "ischr": false,
2026-03-12 10:41:19.798039 | controller |   "isdir": false,
2026-03-12 10:41:19.798055 | controller |   "isfifo": false,
2026-03-12 10:41:19.798071 | controller |   "isgid": false,
2026-03-12 10:41:19.798087 | controller |   "islnk": false,
2026-03-12 10:41:19.798103 | controller |   "isreg": true,
2026-03-12 10:41:19.798118 | controller |   "issock": false,
2026-03-12 10:41:19.798133 | controller |   "isuid": false,
2026-03-12 10:41:19.798149 | controller |   "mode": "0644",
2026-03-12 10:41:19.798164 | controller |   "mtime": 1772006396.9238591,
2026-03-12 10:41:19.798180 | controller |   "nlink": 1,
2026-03-12 10:41:19.798196 | controller |   "path": "/home/zuul/crc-setup.log",
2026-03-12 10:41:19.798217 | controller |   "pw_name": "zuul",
2026-03-12 10:41:19.798234 | controller |   "rgrp": true,
2026-03-12 10:41:19.798250 | controller |   "roth": true,
2026-03-12 10:41:19.798346 | controller |   "rusr": true,
2026-03-12 10:41:19.798372 | controller |   "size": 4108,
2026-03-12 10:41:19.798392 | controller |   "uid": 1000,
2026-03-12 10:41:19.798410 | controller |   "wgrp": false,
2026-03-12 10:41:19.798426 | controller |   "woth": false,
2026-03-12 10:41:19.798444 | controller |   "wusr": true,
2026-03-12 10:41:19.798460 | controller |   "xgrp": false,
2026-03-12 10:41:19.798476 | controller |   "xoth": false,
2026-03-12 10:41:19.798493 | controller |   "xusr": false
2026-03-12 10:41:19.798509 | controller | }
2026-03-12 10:41:20.280335 | controller | changed:
2026-03-12 10:41:20.280444 | controller | {
2026-03-12 10:41:20.280469 | controller |   "atime": 1772006398.6759083,
2026-03-12 10:41:20.280489 | controller |   "ctime": 1772007098.5537844,
2026-03-12 10:41:20.280566 | controller |   "dev": 64513,
2026-03-12 10:41:20.280682 | controller |   "gid": 1000,
2026-03-12 10:41:20.280709 | controller |   "gr_name": "zuul",
2026-03-12 10:41:20.280728 | controller |   "inode": 359205,
2026-03-12 10:41:20.280745 | controller |   "isblk": false,
2026-03-12 10:41:20.280760 | controller |   "ischr": false,
2026-03-12 10:41:20.280774 | controller |   "isdir": false,
2026-03-12 10:41:20.280788 | controller |   "isfifo": false,
2026-03-12 10:41:20.280802 | controller |   "isgid": false,
2026-03-12 10:41:20.280815 | controller |   "islnk": false,
2026-03-12 10:41:20.280829 | controller |   "isreg": true,
2026-03-12 10:41:20.280843 | controller |   "issock": false,
2026-03-12 10:41:20.280919 | controller |   "isuid": false,
2026-03-12 10:41:20.280950 | controller |   "mode": "0644",
2026-03-12 10:41:20.280969 | controller |   "mtime": 1772007098.5537844,
2026-03-12 10:41:20.280985 | controller |   "nlink": 1,
2026-03-12 10:41:20.281000 | controller |   "path": "/home/zuul/crc-start.log",
2026-03-12 10:41:20.281013 | controller |   "pw_name": "zuul",
2026-03-12 10:41:20.281028 | controller |   "rgrp": true,
2026-03-12 10:41:20.281043 | controller |   "roth": true,
2026-03-12 10:41:20.281057 | controller |   "rusr": true,
2026-03-12 10:41:20.281071 | controller |   "size": 4654,
2026-03-12 10:41:20.281086 | controller |   "uid": 1000,
2026-03-12 10:41:20.281100 | controller |   "wgrp": false,
2026-03-12 10:41:20.281115 | controller |   "woth": false,
2026-03-12 10:41:20.281128 | controller |   "wusr": true,
2026-03-12 10:41:20.281142 | controller |   "xgrp": false,
2026-03-12 10:41:20.281155 | controller |   "xoth": false,
2026-03-12 10:41:20.281169 | controller |   "xusr": false
2026-03-12 10:41:20.281182 | controller | }
2026-03-12 10:41:20.783948 | controller | changed:
2026-03-12 10:41:20.784011 | controller | {
2026-03-12 10:41:20.784035 | controller |   "atime": 1773311981.8340123,
2026-03-12 10:41:20.784053 | controller |   "ctime": 1773312012.6689582,
2026-03-12 10:41:20.784068 | controller |   "dev": 64513,
2026-03-12 10:41:20.784088 | controller |   "gid": 1000,
2026-03-12 10:41:20.784102 | controller |   "gr_name": "zuul",
2026-03-12 10:41:20.784116 | controller |   "inode": 1189032,
2026-03-12 10:41:20.784129 | controller |   "isblk": false,
2026-03-12 10:41:20.784142 | controller |   "ischr": false,
2026-03-12 10:41:20.784155 | controller |   "isdir": false,
2026-03-12 10:41:20.784168 | controller |   "isfifo": false,
2026-03-12 10:41:20.784180 | controller |   "isgid": false,
2026-03-12 10:41:20.784192 | controller |   "islnk": false,
2026-03-12 10:41:20.784204 | controller |   "isreg": true,
2026-03-12 10:41:20.784217 | controller |   "issock": false,
2026-03-12 10:41:20.784229 | controller |   "isuid": false,
2026-03-12 10:41:20.784241 | controller |   "mode": "0644",
2026-03-12 10:41:20.784254 | controller |   "mtime": 1773312012.6689582,
2026-03-12 10:41:20.784286 | controller |   "nlink": 1,
2026-03-12 10:41:20.784303 | controller |   "path": "/home/zuul/ansible.log",
2026-03-12 10:41:20.784317 | controller |   "pw_name": "zuul",
2026-03-12 10:41:20.784332 | controller |   "rgrp": true,
2026-03-12 10:41:20.784345 | controller |   "roth": true,
2026-03-12 10:41:20.784360 | controller |   "rusr": true,
2026-03-12 10:41:20.784373 | controller |   "size": 6749,
2026-03-12 10:41:20.784385 | controller |   "uid": 1000,
2026-03-12 10:41:20.784398 | controller |   "wgrp": false,
2026-03-12 10:41:20.784410 | controller |   "woth": false,
2026-03-12 10:41:20.784422 | controller |   "wusr": true,
2026-03-12 10:41:20.784434 | controller |   "xgrp": false,
2026-03-12 10:41:20.784446 | controller |   "xoth": false,
2026-03-12 10:41:20.784458 | controller |   "xusr": false
2026-03-12 10:41:20.784470 | controller | }
2026-03-12 10:41:20.796695 | 
2026-03-12 10:41:20.796760 | TASK [Copy crio stats log file]
2026-03-12 10:41:20.810323 | controller | skipping: Conditional result was False
2026-03-12 10:41:20.815506 | 
2026-03-12 10:41:20.815569 | TASK [Get SELinux related data]
2026-03-12 10:41:21.069240 | controller | <no matches>
2026-03-12 10:41:21.341112 | controller | ERROR
2026-03-12 10:41:21.341325 | controller | {
2026-03-12 10:41:21.341360 | controller |   "delta": "0:00:00.008379",
2026-03-12 10:41:21.341383 | controller |   "end": "2026-03-12 10:41:21.070065",
2026-03-12 10:41:21.341401 | controller |   "msg": "non-zero return code",
2026-03-12 10:41:21.341416 | controller |   "rc": 1,
2026-03-12 10:41:21.341431 | controller |   "start": "2026-03-12 10:41:21.061686"
2026-03-12 10:41:21.341445 | controller | }
2026-03-12 10:41:21.341465 | controller | ERROR: Ignoring Errors
2026-03-12 10:41:21.346773 | 
2026-03-12 10:41:21.346834 | TASK [Create system configuration directory]
2026-03-12 10:41:21.588344 | controller | changed
2026-03-12 10:41:21.593191 | 
2026-03-12 10:41:21.593253 | TASK [Get some of the system configurations]
2026-03-12 10:41:22.119729 | controller | changed
2026-03-12 10:41:22.124376 | 
2026-03-12 10:41:22.124433 | TASK [Copy generated documentation if available]
2026-03-12 10:41:22.138106 | controller | skipping: Conditional result was False
2026-03-12 10:41:22.143671 | 
2026-03-12 10:41:22.143732 | TASK [Copy generated AsciiDoc documentation if available]
2026-03-12 10:41:22.157674 | controller | skipping: Conditional result was False
2026-03-12 10:41:22.163672 | 
2026-03-12 10:41:22.163736 | TASK [Compress logs bigger than 2MB]
2026-03-12 10:41:22.688584 | controller | changed
2026-03-12 10:41:22.693365 | 
2026-03-12 10:41:22.693426 | TASK [Copy files from workspace on node]
2026-03-12 10:41:22.711559 | controller | ok
2026-03-12 10:41:22.732833 | 
2026-03-12 10:41:22.732895 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-12 10:41:22.746038 | controller | skipping: Conditional result was False
2026-03-12 10:41:22.751440 | 
2026-03-12 10:41:22.751511 | TASK [fetch-output : Set log path for single node]
2026-03-12 10:41:22.780208 | controller | ok
2026-03-12 10:41:22.784822 | 
2026-03-12 10:41:22.784882 | LOOP [fetch-output : Ensure local output dirs]
2026-03-12 10:41:22.973248 | controller -> localhost | ok: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/logs"
2026-03-12 10:41:22.973525 | controller -> localhost | changed: All items complete
2026-03-12 10:41:22.973552 | 
2026-03-12 10:41:23.144817 | controller -> localhost | changed: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/artifacts"
2026-03-12 10:41:23.317446 | controller -> localhost | changed: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/docs"
2026-03-12 10:41:23.331007 | 
2026-03-12 10:41:23.331100 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-12 10:41:23.925773 | controller | changed:
2026-03-12 10:41:23.925967 | controller | .d..t...... ./
2026-03-12 10:41:23.925999 | controller | >f+++++++++ README.html
2026-03-12 10:41:23.926020 | controller | >f+++++++++ ansible-execution.log
2026-03-12 10:41:23.926039 | controller | >f+++++++++ ansible.log
2026-03-12 10:41:23.926057 | controller | >f+++++++++ crc-setup.log
2026-03-12 10:41:23.926073 | controller | >f+++++++++ crc-start.log
2026-03-12 10:41:23.926090 | controller | >f+++++++++ dmesg.log
2026-03-12 10:41:23.926113 | controller | >f+++++++++ installed-pkgs.log
2026-03-12 10:41:23.926130 | controller | >f+++++++++ python.log
2026-03-12 10:41:23.926146 | controller | >f+++++++++ registries.conf
2026-03-12 10:41:23.926162 | controller | >f+++++++++ report.html
2026-03-12 10:41:23.926178 | controller | >f+++++++++ selinux-denials.log
2026-03-12 10:41:23.926193 | controller | >f+++++++++ selinux-listing.log
2026-03-12 10:41:23.926209 | controller | cd+++++++++ ci-framework-data/
2026-03-12 10:41:23.926224 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-03-12 10:41:23.926239 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-03-12 10:41:23.926254 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-03-12 10:41:23.926290 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-03-12 10:41:23.926310 | controller | cd+++++++++ ci-framework-data/logs/
2026-03-12 10:41:23.926327 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-03-12 10:41:23.926343 | controller | cd+++++++++ registries.conf.d/
2026-03-12 10:41:23.926358 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-03-12 10:41:23.926374 | controller | cd+++++++++ system-config/
2026-03-12 10:41:23.926391 | controller | cd+++++++++ system-config/libvirt/
2026-03-12 10:41:23.926406 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-03-12 10:41:23.926422 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-03-12 10:41:23.926437 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2026-03-12 10:41:23.926451 | controller | >f+++++++++ system-config/libvirt/network.conf
2026-03-12 10:41:23.926466 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2026-03-12 10:41:23.926480 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2026-03-12 10:41:23.926495 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2026-03-12 10:41:23.926510 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2026-03-12 10:41:23.926525 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2026-03-12 10:41:23.926541 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2026-03-12 10:41:23.926556 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2026-03-12 10:41:23.926571 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2026-03-12 10:41:23.926586 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2026-03-12 10:41:23.926600 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2026-03-12 10:41:23.926613 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2026-03-12 10:41:23.926627 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2026-03-12 10:41:24.354795 | controller | changed: .d..t...... ./
2026-03-12 10:41:24.768414 | controller | changed: .d..t...... ./
2026-03-12 10:41:24.781662 | 
2026-03-12 10:41:24.781760 | TASK [Return artifact to Zuul]
2026-03-12 10:41:24.810150 | controller | ok
2026-03-12 10:41:24.828654 | 
2026-03-12 10:41:24.828715 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-03-12 10:41:24.828814 | 
2026-03-12 10:41:24.828840 | PLAY RECAP
2026-03-12 10:41:24.828878 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-03-12 10:41:24.828899 | 
2026-03-12 10:41:24.906074 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-12 10:41:24.906826 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-12 10:41:25.402185 | 
2026-03-12 10:41:25.402309 | PLAY [all]
2026-03-12 10:41:25.420558 | 
2026-03-12 10:41:25.420631 | TASK [include_role : fetch-output]
2026-03-12 10:41:25.448682 | controller | ok
2026-03-12 10:41:25.464752 | 
2026-03-12 10:41:25.464829 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-12 10:41:25.509118 | controller | skipping: Conditional result was False
2026-03-12 10:41:25.514437 | 
2026-03-12 10:41:25.514508 | TASK [fetch-output : Set log path for single node]
2026-03-12 10:41:25.542612 | controller | ok
2026-03-12 10:41:25.547370 | 
2026-03-12 10:41:25.547439 | LOOP [fetch-output : Ensure local output dirs]
2026-03-12 10:41:25.853921 | controller -> localhost | ok: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/logs"
2026-03-12 10:41:26.035945 | controller -> localhost | ok: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/artifacts"
2026-03-12 10:41:26.209677 | controller -> localhost | ok: "/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/docs"
2026-03-12 10:41:26.225378 | 
2026-03-12 10:41:26.225463 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-12 10:41:26.791704 | controller | ok
2026-03-12 10:41:26.791974 | controller | ok: All items complete
2026-03-12 10:41:26.792009 | 
2026-03-12 10:41:27.238036 | controller | ok
2026-03-12 10:41:27.666583 | controller | ok
2026-03-12 10:41:27.684515 | 
2026-03-12 10:41:27.684619 | TASK [include_role : fetch-output-openshift]
2026-03-12 10:41:27.698191 | controller | skipping: Conditional result was False
2026-03-12 10:41:27.703783 | 
2026-03-12 10:41:27.703852 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-03-12 10:41:28.027400 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006321
2026-03-12 10:41:28.215708 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007499
2026-03-12 10:41:28.246986 | 
2026-03-12 10:41:28.247070 | PLAY [all]
2026-03-12 10:41:28.260570 | 
2026-03-12 10:41:28.260638 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-03-12 10:41:28.716990 | controller | changed
2026-03-12 10:41:28.737815 | 
2026-03-12 10:41:28.737874 | PLAY RECAP
2026-03-12 10:41:28.737931 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-03-12 10:41:28.737957 | 
2026-03-12 10:41:28.802639 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-12 10:41:28.803382 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-03-12 10:41:29.306694 | 
2026-03-12 10:41:29.306800 | PLAY [localhost]
2026-03-12 10:41:29.323818 | 
2026-03-12 10:41:29.323889 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-03-12 10:41:29.615891 | localhost | changed
2026-03-12 10:41:29.630675 | 
2026-03-12 10:41:29.630753 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-03-12 10:41:29.647451 | localhost | ok
2026-03-12 10:41:29.654725 | 
2026-03-12 10:41:29.654792 | TASK [add-fileserver : Create SSH private key tempfile]
2026-03-12 10:41:29.935502 | localhost | changed
2026-03-12 10:41:29.941001 | 
2026-03-12 10:41:29.941073 | TASK [add-fileserver : Create SSH private key from secret]
2026-03-12 10:41:30.464420 | localhost | changed
2026-03-12 10:41:30.469157 | 
2026-03-12 10:41:30.469229 | TASK [add-fileserver : Add fileserver ssh key]
2026-03-12 10:41:30.779698 | localhost | Identity added: /var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/tmp/ansible.88q6jidk (/var/lib/zuul/builds/a2b351dfb56646f4bf330d423e352d33/work/tmp/ansible.88q6jidk)
2026-03-12 10:41:30.779870 | localhost | ok: Runtime: 0:00:00.006073
2026-03-12 10:41:30.784120 | 
2026-03-12 10:41:30.784193 | TASK [add-fileserver : Remove SSH private key from disk]
2026-03-12 10:41:30.994004 | localhost | ok: Runtime: 0:00:00.003571
2026-03-12 10:41:30.998549 | 
2026-03-12 10:41:30.998617 | TASK [add-fileserver : Add fileserver to inventory]
2026-03-12 10:41:31.045444 | localhost | changed
2026-03-12 10:41:31.050099 | 
2026-03-12 10:41:31.050166 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-03-12 10:41:31.330157 | localhost | changed
2026-03-12 10:41:31.347113 | 
2026-03-12 10:41:31.347165 | PLAY [localhost]
2026-03-12 10:41:31.357169 | 
2026-03-12 10:41:31.357223 | TASK [Generate bulk log download script]
2026-03-12 10:41:31.373807 | localhost | ok
2026-03-12 10:41:31.383807 | 
2026-03-12 10:41:31.383867 | TASK [local-log-download : Check API endpoint is defined]
2026-03-12 10:41:31.410006 | localhost | ok: All assertions passed
2026-03-12 10:41:31.413935 | 
2026-03-12 10:41:31.413994 | TASK [local-log-download : Create download script]
2026-03-12 10:41:31.740737 | localhost -> localhost | changed
2026-03-12 10:41:31.748651 | 
2026-03-12 10:41:31.748717 | TASK [Register quick-download link]
2026-03-12 10:41:31.765277 | localhost | ok
2026-03-12 10:41:31.797000 | 
2026-03-12 10:41:31.797066 | PLAY [logserver.rdoproject.org]
2026-03-12 10:41:31.806165 | 
2026-03-12 10:41:31.806224 | TASK [Set zuul-log-path fact]
2026-03-12 10:41:31.821569 | logserver.rdoproject.org | ok
2026-03-12 10:41:31.829812 | 
2026-03-12 10:41:31.829877 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-12 10:41:31.845003 | logserver.rdoproject.org | ok
2026-03-12 10:41:31.849731 | 
2026-03-12 10:41:31.849790 | TASK [upload-logs : Create log directories]
2026-03-12 10:41:33.519389 | logserver.rdoproject.org | changed
2026-03-12 10:41:33.522439 | 
2026-03-12 10:41:33.522507 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-03-12 10:41:33.728607 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.003690
2026-03-12 10:41:33.733012 | 
2026-03-12 10:41:33.733079 | TASK [upload-logs : Upload logs to log server]
2026-03-12 10:41:35.207447 | logserver.rdoproject.org | Output suppressed because no_log was given
2026-03-12 10:41:35.210221 | 
2026-03-12 10:41:35.210323 | LOOP [upload-logs : Compress console log and json output]
2026-03-12 10:41:35.247851 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 10:41:35.255154 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 10:41:35.267665 | 
2026-03-12 10:41:35.267748 | LOOP [upload-logs : Upload compressed console log and json output]
2026-03-12 10:41:35.299736 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 10:41:35.299984 | 
2026-03-12 10:41:35.302994 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 10:41:35.314213 | 
2026-03-12 10:41:35.314313 | LOOP [upload-logs : Upload console log and json output]