2026-03-12 11:57:10.838956 | Job console starting...
2026-03-12 11:57:11.044982 | Updating repositories
2026-03-12 11:57:11.066578 | Preparing job workspace
2026-03-12 11:57:17.918338 | Running Ansible setup...
2026-03-12 11:57:21.552818 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-12 11:57:22.044560 | 
2026-03-12 11:57:22.044660 | PLAY [localhost]
2026-03-12 11:57:22.053187 | 
2026-03-12 11:57:22.053255 | TASK [Gathering Facts]
2026-03-12 11:57:22.867749 | localhost | ok
2026-03-12 11:57:22.881623 | 
2026-03-12 11:57:22.881753 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-03-12 11:57:23.209137 | localhost -> localhost | changed
2026-03-12 11:57:23.214582 | 
2026-03-12 11:57:23.214659 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-03-12 11:57:23.897092 | localhost -> localhost | changed
2026-03-12 11:57:23.905590 | 
2026-03-12 11:57:23.905669 | TASK [Setup log path fact]
2026-03-12 11:57:23.923154 | localhost | ok
2026-03-12 11:57:23.935270 | 
2026-03-12 11:57:23.935371 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-12 11:57:23.953877 | localhost | ok
2026-03-12 11:57:23.961469 | 
2026-03-12 11:57:23.961535 | TASK [emit-job-header : Print job information]
2026-03-12 11:57:23.988539 | # Job Information
2026-03-12 11:57:23.988661 | Ansible Version: 2.15.12
2026-03-12 11:57:23.988690 | Job: cifmw-molecule-reproducer
2026-03-12 11:57:23.988711 | Pipeline: github-check
2026-03-12 11:57:23.988730 | Executor: ibm-bm4-ze.softwarefactory-project.io
2026-03-12 11:57:23.988749 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3739
2026-03-12 11:57:23.988768 | Log URL (when completed): https://logserver.rdoproject.org/d3a/rdoproject.org/d3a5949a26c648c1942a9be4304559e1/
2026-03-12 11:57:23.988787 | Event ID: 736cea60-1e0a-11f1-86a3-e73a706f10e2
2026-03-12 11:57:23.992222 | 
2026-03-12 11:57:23.992286 | LOOP [emit-job-header : Print node information]
2026-03-12 11:57:24.078990 | localhost | ok:
2026-03-12 11:57:24.079188 | localhost | # Node Information
2026-03-12 11:57:24.079221 | localhost | Inventory Hostname: controller
2026-03-12 11:57:24.079247 | localhost | Hostname: np0005645314
2026-03-12 11:57:24.079270 | localhost | Username: zuul
2026-03-12 11:57:24.079307 | localhost | Distro: CentOS 9
2026-03-12 11:57:24.079336 | localhost | Provider: ibm-bm4-nodepool
2026-03-12 11:57:24.079358 | localhost | Region: regionOne
2026-03-12 11:57:24.079376 | localhost | Label: centos-9-stream-crc-2-48-0-xxl-ibm
2026-03-12 11:57:24.079395 | localhost | Product Name: OpenStack Compute
2026-03-12 11:57:24.079412 | localhost | Interface IP: 192.168.26.171
2026-03-12 11:57:24.107467 | 
2026-03-12 11:57:24.107542 | PLAY [all]
2026-03-12 11:57:24.113738 | 
2026-03-12 11:57:24.113803 | TASK [Gather network facts]
2026-03-12 11:57:24.560638 | controller | ok
2026-03-12 11:57:24.574892 | 
2026-03-12 11:57:24.574970 | TASK [include_role : start-zuul-console]
2026-03-12 11:57:24.593737 | controller | ok
2026-03-12 11:57:24.604970 | 
2026-03-12 11:57:24.605036 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-03-12 11:57:24.987328 | controller | ok
2026-03-12 11:57:24.995884 | 
2026-03-12 11:57:24.995955 | TASK [include_role : add-build-sshkey]
2026-03-12 11:57:25.014053 | controller | ok
2026-03-12 11:57:25.026939 | 
2026-03-12 11:57:25.027013 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-03-12 11:57:25.222923 | controller -> localhost | ok
2026-03-12 11:57:25.228355 | 
2026-03-12 11:57:25.228422 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-03-12 11:57:25.247112 | controller | ok
2026-03-12 11:57:25.259770 | controller | included: /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-03-12 11:57:25.265412 | 
2026-03-12 11:57:25.265476 | TASK [add-build-sshkey : Create Temp SSH key]
2026-03-12 11:57:25.643008 | controller -> localhost | Generating public/private rsa key pair.
2026-03-12 11:57:25.643205 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/d3a5949a26c648c1942a9be4304559e1_id_rsa.
2026-03-12 11:57:25.643240 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/d3a5949a26c648c1942a9be4304559e1_id_rsa.pub.
2026-03-12 11:57:25.643265 | controller -> localhost | The key fingerprint is:
2026-03-12 11:57:25.643288 | controller -> localhost | SHA256:tmOPLiL2vnWvosjR9/GjCxh0L+2/SmtjJIBg/xCfTbY zuul-build-sshkey
2026-03-12 11:57:25.643335 | controller -> localhost | The key's randomart image is:
2026-03-12 11:57:25.643359 | controller -> localhost | +---[RSA 3072]----+
2026-03-12 11:57:25.643381 | controller -> localhost | |                 |
2026-03-12 11:57:25.643401 | controller -> localhost | |.. .   o         |
2026-03-12 11:57:25.643420 | controller -> localhost | |....+ * .        |
2026-03-12 11:57:25.643440 | controller -> localhost | |  .+.+ E         |
2026-03-12 11:57:25.643458 | controller -> localhost | |    +.. S        |
2026-03-12 11:57:25.643477 | controller -> localhost | |   . +.+..       |
2026-03-12 11:57:25.643494 | controller -> localhost | |  . o +oO        |
2026-03-12 11:57:25.643512 | controller -> localhost | | .oo.oo*+X.      |
2026-03-12 11:57:25.643529 | controller -> localhost | | .o+=+ *X**o     |
2026-03-12 11:57:25.643547 | controller -> localhost | +----[SHA256]-----+
2026-03-12 11:57:25.643599 | controller -> localhost | ok: Runtime: 0:00:00.055812
2026-03-12 11:57:25.649217 | 
2026-03-12 11:57:25.649286 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-03-12 11:57:25.667206 | controller | ok
2026-03-12 11:57:25.676494 | controller | included: /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-03-12 11:57:25.684329 | 
2026-03-12 11:57:25.684395 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-03-12 11:57:25.697602 | controller | skipping: Conditional result was False
2026-03-12 11:57:25.702887 | 
2026-03-12 11:57:25.702954 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-03-12 11:57:26.178780 | controller | changed
2026-03-12 11:57:26.183551 | 
2026-03-12 11:57:26.183626 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-03-12 11:57:26.481349 | controller | ok
2026-03-12 11:57:26.486228 | 
2026-03-12 11:57:26.496315 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-03-12 11:57:27.789314 | controller | changed
2026-03-12 11:57:27.794208 | 
2026-03-12 11:57:27.794277 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-03-12 11:57:28.996434 | controller | changed
2026-03-12 11:57:29.001187 | 
2026-03-12 11:57:29.001250 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-03-12 11:57:29.014615 | controller | skipping: Conditional result was False
2026-03-12 11:57:29.019941 | 
2026-03-12 11:57:29.020006 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-03-12 11:57:29.316679 | controller -> localhost | changed
2026-03-12 11:57:29.326557 | 
2026-03-12 11:57:29.326639 | TASK [add-build-sshkey : Add back temp key]
2026-03-12 11:57:29.552768 | controller -> localhost | Identity added: /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/d3a5949a26c648c1942a9be4304559e1_id_rsa (zuul-build-sshkey)
2026-03-12 11:57:29.552947 | controller -> localhost | ok: Runtime: 0:00:00.006399
2026-03-12 11:57:29.559379 | 
2026-03-12 11:57:29.559449 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-03-12 11:57:29.922862 | controller | ok
2026-03-12 11:57:29.927317 | 
2026-03-12 11:57:29.927386 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-03-12 11:57:29.951196 | controller | skipping: Conditional result was False
2026-03-12 11:57:29.960402 | 
2026-03-12 11:57:29.960468 | TASK [include_role : validate-host]
2026-03-12 11:57:29.978169 | controller | ok
2026-03-12 11:57:29.997008 | 
2026-03-12 11:57:29.997081 | TASK [validate-host : Define zuul_info_dir fact]
2026-03-12 11:57:30.025122 | controller | ok
2026-03-12 11:57:30.029574 | 
2026-03-12 11:57:30.029635 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-03-12 11:57:30.235867 | controller -> localhost | ok
2026-03-12 11:57:30.243251 | 
2026-03-12 11:57:30.243346 | TASK [validate-host : Collect information about the host]
2026-03-12 11:57:30.977854 | controller | ok
2026-03-12 11:57:30.986207 | 
2026-03-12 11:57:30.986277 | TASK [validate-host : Sanitize hostname]
2026-03-12 11:57:31.036584 | controller | ok
2026-03-12 11:57:31.042132 | 
2026-03-12 11:57:31.042230 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-03-12 11:57:31.443366 | controller -> localhost | changed
2026-03-12 11:57:31.449208 | 
2026-03-12 11:57:31.449276 | TASK [validate-host : Collect information about zuul worker]
2026-03-12 11:57:31.861405 | controller | ok
2026-03-12 11:57:31.866639 | 
2026-03-12 11:57:31.866727 | TASK [validate-host : Write out all zuul information for each host]
2026-03-12 11:57:32.251766 | controller -> localhost | changed
2026-03-12 11:57:32.262387 | 
2026-03-12 11:57:32.262472 | TASK [include_role : prepare-workspace-openshift]
2026-03-12 11:57:32.277024 | controller | skipping: Conditional result was False
2026-03-12 11:57:32.283089 | 
2026-03-12 11:57:32.283171 | TASK [include_role : remove-zuul-sshkey]
2026-03-12 11:57:32.296886 | controller | skipping: Conditional result was False
2026-03-12 11:57:32.302535 | 
2026-03-12 11:57:32.302605 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-03-12 11:57:32.590346 | controller | ok: "logs"
2026-03-12 11:57:32.590586 | controller | ok: All items complete
2026-03-12 11:57:32.590621 | 
2026-03-12 11:57:32.828032 | controller | ok: "artifacts"
2026-03-12 11:57:33.063611 | controller | ok: "docs"
2026-03-12 11:57:33.074009 | 
2026-03-12 11:57:33.074117 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-03-12 11:57:33.370997 | controller | changed: "logs"
2026-03-12 11:57:33.621145 | controller | changed: "artifacts"
2026-03-12 11:57:33.877754 | controller | changed: "docs"
2026-03-12 11:57:33.906068 | 
2026-03-12 11:57:33.906148 | PLAY RECAP
2026-03-12 11:57:33.906193 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-12 11:57:33.906221 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-12 11:57:33.906240 | 
2026-03-12 11:57:33.981951 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-12 11:57:33.982863 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-12 11:57:34.554344 | 
2026-03-12 11:57:34.554514 | PLAY [all]
2026-03-12 11:57:34.573843 | 
2026-03-12 11:57:34.573910 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-12 11:57:34.623281 | controller | ok
2026-03-12 11:57:34.628517 | 
2026-03-12 11:57:34.628599 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-12 11:57:35.060482 | controller | changed
2026-03-12 11:57:35.066233 | 
2026-03-12 11:57:35.066361 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-12 11:57:36.548907 | controller | changed
2026-03-12 11:57:36.558714 | 
2026-03-12 11:57:36.558803 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-03-12 11:57:37.015738 | controller | changed:
2026-03-12 11:57:37.016007 | controller | {
2026-03-12 11:57:37.016045 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-03-12 11:57:37.016078 | controller | }
2026-03-12 11:57:37.325225 | controller | changed:
2026-03-12 11:57:37.325336 | controller | {
2026-03-12 11:57:37.325367 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-03-12 11:57:37.325389 | controller | }
2026-03-12 11:57:37.618501 | controller | changed:
2026-03-12 11:57:37.618724 | controller | {
2026-03-12 11:57:37.618750 | 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 11:57:37.618782 | controller | }
2026-03-12 11:57:37.915602 | controller | changed:
2026-03-12 11:57:37.915775 | controller | {
2026-03-12 11:57:37.915803 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-03-12 11:57:37.915824 | controller | }
2026-03-12 11:57:38.212274 | controller | changed:
2026-03-12 11:57:38.212480 | controller | {
2026-03-12 11:57:38.212508 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-03-12 11:57:38.212530 | controller | }
2026-03-12 11:57:38.504982 | controller | changed:
2026-03-12 11:57:38.505122 | controller | {
2026-03-12 11:57:38.505153 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-03-12 11:57:38.505174 | controller | }
2026-03-12 11:57:38.802727 | controller | changed:
2026-03-12 11:57:38.802822 | controller | {
2026-03-12 11:57:38.802850 | 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 11:57:38.802872 | controller | }
2026-03-12 11:57:39.096316 | controller | changed:
2026-03-12 11:57:39.096390 | controller | {
2026-03-12 11:57:39.096418 | 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 11:57:39.096439 | controller | }
2026-03-12 11:57:39.404747 | controller | changed:
2026-03-12 11:57:39.404860 | controller | {
2026-03-12 11:57:39.404888 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-03-12 11:57:39.404909 | controller | }
2026-03-12 11:57:39.726743 | controller | changed:
2026-03-12 11:57:39.726901 | controller | {
2026-03-12 11:57:39.726937 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-03-12 11:57:39.726961 | controller | }
2026-03-12 11:57:40.022212 | controller | changed:
2026-03-12 11:57:40.022307 | controller | {
2026-03-12 11:57:40.022341 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-03-12 11:57:40.022364 | controller | }
2026-03-12 11:57:40.341849 | controller | changed:
2026-03-12 11:57:40.341912 | controller | {
2026-03-12 11:57:40.341937 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-03-12 11:57:40.341956 | controller | }
2026-03-12 11:57:40.674928 | controller | changed:
2026-03-12 11:57:40.675031 | controller | {
2026-03-12 11:57:40.675058 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-03-12 11:57:40.675079 | controller | }
2026-03-12 11:57:40.987937 | controller | changed:
2026-03-12 11:57:40.988032 | controller | {
2026-03-12 11:57:40.988059 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-03-12 11:57:40.988080 | controller | }
2026-03-12 11:57:41.305111 | controller | changed:
2026-03-12 11:57:41.305196 | controller | {
2026-03-12 11:57:41.305224 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-03-12 11:57:41.305246 | controller | }
2026-03-12 11:57:41.622284 | controller | changed:
2026-03-12 11:57:41.622390 | controller | {
2026-03-12 11:57:41.622416 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-03-12 11:57:41.622436 | controller | }
2026-03-12 11:57:41.918597 | controller | changed:
2026-03-12 11:57:41.918664 | controller | {
2026-03-12 11:57:41.918690 | 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 11:57:41.918710 | controller | }
2026-03-12 11:57:42.252134 | controller | changed:
2026-03-12 11:57:42.252258 | controller | {
2026-03-12 11:57:42.252323 | 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 11:57:42.252504 | controller | }
2026-03-12 11:57:42.590613 | controller | changed:
2026-03-12 11:57:42.590931 | controller | {
2026-03-12 11:57:42.590962 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-03-12 11:57:42.591137 | controller | }
2026-03-12 11:57:42.884373 | controller | changed:
2026-03-12 11:57:42.884482 | controller | {
2026-03-12 11:57:42.884511 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-03-12 11:57:42.884534 | controller | }
2026-03-12 11:57:43.192696 | controller | changed:
2026-03-12 11:57:43.192819 | controller | {
2026-03-12 11:57:43.192857 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-03-12 11:57:43.192881 | controller | }
2026-03-12 11:57:43.501786 | controller | changed:
2026-03-12 11:57:43.501910 | controller | {
2026-03-12 11:57:43.501938 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-03-12 11:57:43.501960 | controller | }
2026-03-12 11:57:43.815000 | controller | changed:
2026-03-12 11:57:43.815075 | controller | {
2026-03-12 11:57:43.815101 | 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 11:57:43.815122 | controller | }
2026-03-12 11:57:44.118102 | controller | changed:
2026-03-12 11:57:44.118220 | controller | {
2026-03-12 11:57:44.118248 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-03-12 11:57:44.118268 | controller | }
2026-03-12 11:57:44.428156 | controller | changed:
2026-03-12 11:57:44.428257 | controller | {
2026-03-12 11:57:44.428285 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-03-12 11:57:44.428331 | controller | }
2026-03-12 11:57:44.747105 | controller | changed:
2026-03-12 11:57:44.747346 | controller | {
2026-03-12 11:57:44.747414 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-03-12 11:57:44.747439 | controller | }
2026-03-12 11:57:44.772606 | 
2026-03-12 11:57:44.772709 | TASK [Set timezone to UTC]
2026-03-12 11:57:45.298894 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-03-12 11:57:45.303950 | 
2026-03-12 11:57:45.304015 | TASK [Create nodepool directory]
2026-03-12 11:57:45.588712 | controller | changed
2026-03-12 11:57:45.594346 | 
2026-03-12 11:57:45.594410 | TASK [Create nodepool sub_nodes file]
2026-03-12 11:57:46.644973 | controller | changed
2026-03-12 11:57:46.651985 | 
2026-03-12 11:57:46.652052 | TASK [Create nodepool sub_nodes_private file]
2026-03-12 11:57:47.676221 | controller | changed
2026-03-12 11:57:47.681173 | 
2026-03-12 11:57:47.681254 | LOOP [Populate nodepool sub_nodes file]
2026-03-12 11:57:47.710335 | 
2026-03-12 11:57:47.710453 | LOOP [Populate nodepool sub_nodes_private file]
2026-03-12 11:57:47.738768 | 
2026-03-12 11:57:47.738884 | TASK [Create nodepool primary file]
2026-03-12 11:57:47.762325 | controller | skipping: Conditional result was False
2026-03-12 11:57:47.767513 | 
2026-03-12 11:57:47.767585 | TASK [Create nodepool node_private for this node]
2026-03-12 11:57:48.884954 | controller | changed
2026-03-12 11:57:48.890941 | 
2026-03-12 11:57:48.891013 | LOOP [Copy ssh keys to nodepool directory]
2026-03-12 11:57:49.305368 | controller | ok: Item: id_rsa Runtime: 0:00:00.005990
2026-03-12 11:57:49.305722 | 
2026-03-12 11:57:49.544259 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006593
2026-03-12 11:57:49.555468 | 
2026-03-12 11:57:49.555570 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-03-12 11:57:50.669855 | controller | changed
2026-03-12 11:57:50.675442 | 
2026-03-12 11:57:50.675571 | TASK [Validate sudoers config after edits]
2026-03-12 11:57:50.972422 | controller | /etc/sudoers: parsed OK
2026-03-12 11:57:50.972479 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-03-12 11:57:50.972488 | controller | /etc/sudoers.d/zuul: parsed OK
2026-03-12 11:57:50.972494 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-03-12 11:57:51.204720 | controller | ok: Runtime: 0:00:00.006094
2026-03-12 11:57:51.210019 | 
2026-03-12 11:57:51.210086 | TASK [Show the environment passed in to job shell scripts]
2026-03-12 11:57:51.510839 | controller | SHELL=/bin/bash
2026-03-12 11:57:51.510891 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-03-12 11:57:51.510902 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-03-12 11:57:51.510909 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/39/3739/fed747f0793a5276bcc94cfdbd33034cb37d1002
2026-03-12 11:57:51.510965 | controller | PWD=/home/zuul
2026-03-12 11:57:51.510974 | controller | ZUUL_PIPELINE=github-check
2026-03-12 11:57:51.510980 | controller | LOGNAME=zuul
2026-03-12 11:57:51.510986 | controller | XDG_SESSION_TYPE=tty
2026-03-12 11:57:51.510992 | controller | _=/usr/bin/env
2026-03-12 11:57:51.510997 | controller | MOTD_SHOWN=pam
2026-03-12 11:57:51.511003 | controller | HOME=/home/zuul
2026-03-12 11:57:51.511008 | controller | LANG=en_US.UTF-8
2026-03-12 11:57:51.511014 | controller | SSH_CONNECTION=192.168.26.12 59558 192.168.26.171 22
2026-03-12 11:57:51.511020 | 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 11:57:51.511030 | controller | ZUUL_CHANGE_IDS=3739,fed747f0793a5276bcc94cfdbd33034cb37d1002
2026-03-12 11:57:51.511035 | controller | WORKSPACE=/home/zuul/workspace
2026-03-12 11:57:51.511041 | controller | XDG_SESSION_CLASS=user
2026-03-12 11:57:51.511047 | controller | SELINUX_ROLE_REQUESTED=
2026-03-12 11:57:51.511052 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-03-12 11:57:51.511058 | controller | USER=zuul
2026-03-12 11:57:51.511063 | controller | ZUUL_VOTING=True
2026-03-12 11:57:51.511069 | controller | BUILD_TIMEOUT=5400000
2026-03-12 11:57:51.511074 | controller | SELINUX_USE_CURRENT_RANGE=
2026-03-12 11:57:51.511079 | controller | SHLVL=1
2026-03-12 11:57:51.511085 | controller | ZUUL_PATCHSET=fed747f0793a5276bcc94cfdbd33034cb37d1002
2026-03-12 11:57:51.511091 | controller | XDG_SESSION_ID=1
2026-03-12 11:57:51.511096 | controller | ZUUL_BRANCH=main
2026-03-12 11:57:51.511102 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-03-12 11:57:51.511107 | controller | SSH_CLIENT=192.168.26.12 59558 22
2026-03-12 11:57:51.511114 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-03-12 11:57:51.511120 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-03-12 11:57:51.511126 | controller | which_declare=declare -f
2026-03-12 11:57:51.511133 | 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 11:57:51.511138 | controller | SELINUX_LEVEL_REQUESTED=
2026-03-12 11:57:51.511144 | controller | ZUUL_CHANGE=3739
2026-03-12 11:57:51.511149 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-03-12 11:57:51.511155 | controller | ZUUL_UUID=d3a5949a26c648c1942a9be4304559e1
2026-03-12 11:57:51.511160 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-03-12 11:57:51.511166 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-03-12 11:57:51.511172 | controller | }
2026-03-12 11:57:51.732623 | controller | ok: Runtime: 0:00:00.006519
2026-03-12 11:57:51.738029 | 
2026-03-12 11:57:51.738093 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-03-12 11:57:51.762931 | controller | skipping: Conditional result was False
2026-03-12 11:57:51.768730 | 
2026-03-12 11:57:51.768797 | TASK [Symlink /home/zuul-worker/workspace]
2026-03-12 11:57:52.337038 | controller | skipping: Conditional result was False
2026-03-12 11:57:52.343401 | 
2026-03-12 11:57:52.343472 | TASK [Ensure legacy workspace directory]
2026-03-12 11:57:52.606952 | controller | changed
2026-03-12 11:57:52.624995 | 
2026-03-12 11:57:52.625058 | PLAY RECAP
2026-03-12 11:57:52.625103 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-12 11:57:52.625125 | 
2026-03-12 11:57:52.722899 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-12 11:57:52.723668 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-12 11:57:53.232403 | 
2026-03-12 11:57:53.232521 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-03-12 11:57:53.252800 | 
2026-03-12 11:57:53.252876 | TASK [Create zuul-output directory]
2026-03-12 11:57:53.679798 | controller | changed
2026-03-12 11:57:53.684799 | 
2026-03-12 11:57:53.684874 | TASK [Slurp Zuul inventory test]
2026-03-12 11:57:53.962974 | controller -> localhost | ok
2026-03-12 11:57:53.969318 | 
2026-03-12 11:57:53.969390 | TASK [Save zuul inventory]
2026-03-12 11:57:55.273552 | controller | changed
2026-03-12 11:57:55.280032 | 
2026-03-12 11:57:55.280151 | TASK [Save zuul vars without the change_message]
2026-03-12 11:57:56.363549 | controller | changed
2026-03-12 11:57:56.381932 | 
2026-03-12 11:57:56.381984 | PLAY RECAP
2026-03-12 11:57:56.382027 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-12 11:57:56.382049 | 
2026-03-12 11:57:56.449238 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-12 11:57:56.450191 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-12 11:57:57.028040 | 
2026-03-12 11:57:57.028171 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-03-12 11:57:57.049240 | 
2026-03-12 11:57:57.049333 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-03-12 11:57:57.069401 | controller | ok
2026-03-12 11:57:57.085852 | 
2026-03-12 11:57:57.085961 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-12 11:57:57.110108 | controller | skipping: Conditional result was False
2026-03-12 11:57:57.115756 | 
2026-03-12 11:57:57.115826 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-12 11:57:57.509443 | controller | ok
2026-03-12 11:57:57.516040 | 
2026-03-12 11:57:57.516117 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-12 11:57:58.518961 | controller | ok
2026-03-12 11:57:58.528103 | 
2026-03-12 11:57:58.528170 | TASK [Prepare workspace]
2026-03-12 11:57:58.547255 | controller | ok
2026-03-12 11:57:58.564015 | 
2026-03-12 11:57:58.564088 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-03-12 11:57:58.950634 | controller | ok
2026-03-12 11:57:58.956782 | 
2026-03-12 11:57:58.956852 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-03-12 11:58:01.459475 | controller | Output suppressed because no_log was given
2026-03-12 11:58:01.468762 | 
2026-03-12 11:58:01.468832 | LOOP [Create zuul-output directory]
2026-03-12 11:58:01.719170 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-03-12 11:58:01.945867 | controller | ok: "/home/zuul/zuul-output/logs"
2026-03-12 11:58:01.955762 | 
2026-03-12 11:58:01.955877 | TASK [Install required packages]
2026-03-12 11:58:18.123626 | controller | ok: Nothing to do
2026-03-12 11:58:18.128686 | 
2026-03-12 11:58:18.128768 | TASK [Install venv]
2026-03-12 11:59:16.775398 | controller | changed
2026-03-12 11:59:16.802581 | 
2026-03-12 11:59:16.802719 | PLAY RECAP
2026-03-12 11:59:16.802771 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-03-12 11:59:16.802794 | 
2026-03-12 11:59:16.882207 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-12 11:59:16.883028 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-12 11:59:17.378489 | 
2026-03-12 11:59:17.378586 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-03-12 11:59:17.398144 | 
2026-03-12 11:59:17.398217 | TASK [Gather required facts]
2026-03-12 11:59:17.995073 | controller | ok
2026-03-12 11:59:18.000483 | 
2026-03-12 11:59:18.000562 | TASK [Load environment var if instructed to]
2026-03-12 11:59:18.026479 | controller | skipping: Conditional result was False
2026-03-12 11:59:18.032405 | 
2026-03-12 11:59:18.032475 | TASK [Ensure group_vars dir exists]
2026-03-12 11:59:18.448589 | controller | ok
2026-03-12 11:59:18.453823 | 
2026-03-12 11:59:18.453892 | TASK [Print related variables]
2026-03-12 11:59:18.484279 | controller | ok:
2026-03-12 11:59:18.484411 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-03-12 11:59:18.484442 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer
2026-03-12 11:59:18.489204 | 
2026-03-12 11:59:18.489271 | TASK [Run molecule]
2026-03-12 11:59:19.538782 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-03-12 11:59:19.886297 | controller | INFO     Running bm_redfish > prepare
2026-03-12 11:59:20.543637 | controller |
2026-03-12 11:59:20.543746 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-03-12 11:59:20.543842 | controller |
2026-03-12 11:59:20.543944 | controller | TASK [Create mock server directory] ********************************************
2026-03-12 11:59:20.544041 | controller | Thursday 12 March 2026  11:59:20 +0000 (0:00:00.026)       0:00:00.026 ********
2026-03-12 11:59:20.885270 | controller | changed: [instance]
2026-03-12 11:59:20.885312 | controller |
2026-03-12 11:59:20.885446 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-03-12 11:59:20.885571 | controller | Thursday 12 March 2026  11:59:20 +0000 (0:00:00.342)       0:00:00.368 ********
2026-03-12 11:59:21.244294 | controller | changed: [instance]
2026-03-12 11:59:21.244336 | controller |
2026-03-12 11:59:21.244457 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-03-12 11:59:21.244578 | controller | Thursday 12 March 2026  11:59:21 +0000 (0:00:00.359)       0:00:00.728 ********
2026-03-12 11:59:21.763074 | controller | changed: [instance]
2026-03-12 11:59:21.763117 | controller |
2026-03-12 11:59:21.763220 | controller | TASK [Start mock iDRAC server] *************************************************
2026-03-12 11:59:21.763317 | controller | Thursday 12 March 2026  11:59:21 +0000 (0:00:00.518)       0:00:01.246 ********
2026-03-12 11:59:21.958632 | controller | changed: [instance]
2026-03-12 11:59:21.958705 | controller |
2026-03-12 11:59:21.959325 | controller | TASK [Record mock server PID] **************************************************
2026-03-12 11:59:21.959437 | controller | Thursday 12 March 2026  11:59:21 +0000 (0:00:00.196)       0:00:01.442 ********
2026-03-12 11:59:22.173335 | controller | ok: [instance]
2026-03-12 11:59:22.173383 | controller |
2026-03-12 11:59:22.173484 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-03-12 11:59:22.173660 | controller | Thursday 12 March 2026  11:59:22 +0000 (0:00:00.214)       0:00:01.657 ********
2026-03-12 11:59:22.607709 | controller | ok: [instance]
2026-03-12 11:59:22.607748 | controller |
2026-03-12 11:59:22.607867 | controller | PLAY RECAP *********************************************************************
2026-03-12 11:59:22.607966 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-03-12 11:59:22.608051 | controller |
2026-03-12 11:59:22.608142 | controller | Thursday 12 March 2026  11:59:22 +0000 (0:00:00.434)       0:00:02.091 ********
2026-03-12 11:59:22.608219 | controller | ===============================================================================
2026-03-12 11:59:22.608313 | controller | Copy mock iDRAC server script ------------------------------------------- 0.52s
2026-03-12 11:59:22.608403 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.43s
2026-03-12 11:59:22.608493 | controller | Generate self-signed TLS certificate ------------------------------------ 0.36s
2026-03-12 11:59:22.608602 | controller | Create mock server directory -------------------------------------------- 0.34s
2026-03-12 11:59:22.608697 | controller | Record mock server PID -------------------------------------------------- 0.21s
2026-03-12 11:59:22.608793 | controller | Start mock iDRAC server ------------------------------------------------- 0.20s
2026-03-12 11:59:22.672600 | controller | INFO     Running bm_redfish > converge
2026-03-12 11:59:23.092337 | controller |
2026-03-12 11:59:23.092465 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-03-12 11:59:23.092560 | controller |
2026-03-12 11:59:23.092671 | controller | TASK [Test bm_power_off] *******************************************************
2026-03-12 11:59:23.092769 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.054)       0:00:00.054 ********
2026-03-12 11:59:23.117328 | 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 11:59:23.117457 | controller |
2026-03-12 11:59:23.117481 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-12 11:59:23.117535 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.025)       0:00:00.080 ********
2026-03-12 11:59:23.530102 | controller | ok: [instance]
2026-03-12 11:59:23.530145 | controller |
2026-03-12 11:59:23.530264 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-12 11:59:23.530355 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.412)       0:00:00.493 ********
2026-03-12 11:59:23.558100 | controller |
2026-03-12 11:59:23.558185 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:23.558284 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.028)       0:00:00.521 ********
2026-03-12 11:59:23.854138 | controller | ok: [instance]
2026-03-12 11:59:23.854195 | controller |
2026-03-12 11:59:23.854331 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 11:59:23.854410 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.295)       0:00:00.817 ********
2026-03-12 11:59:23.873782 | controller | skipping: [instance]
2026-03-12 11:59:23.873851 | controller |
2026-03-12 11:59:23.874035 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 11:59:23.874126 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.019)       0:00:00.836 ********
2026-03-12 11:59:23.893873 | controller | skipping: [instance]
2026-03-12 11:59:23.893935 | controller |
2026-03-12 11:59:23.894051 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-03-12 11:59:23.894144 | controller | Thursday 12 March 2026  11:59:23 +0000 (0:00:00.020)       0:00:00.857 ********
2026-03-12 11:59:24.187197 | controller | ok: [instance]
2026-03-12 11:59:24.187274 | controller |
2026-03-12 11:59:24.187410 | controller | TASK [Assert host is still Off] ************************************************
2026-03-12 11:59:24.187456 | controller | Thursday 12 March 2026  11:59:24 +0000 (0:00:00.292)       0:00:01.149 ********
2026-03-12 11:59:24.209618 | controller | ok: [instance] => {
2026-03-12 11:59:24.210041 | controller |     "changed": false,
2026-03-12 11:59:24.210062 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:24.486945 | controller | }
2026-03-12 11:59:24.486963 | controller |
2026-03-12 11:59:24.486970 | controller | TASK [Reset mock to power On] **************************************************
2026-03-12 11:59:24.486976 | controller | Thursday 12 March 2026  11:59:24 +0000 (0:00:00.022)       0:00:01.172 ********
2026-03-12 11:59:24.486984 | controller | ok: [instance]
2026-03-12 11:59:24.512022 | controller |
2026-03-12 11:59:24.512041 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-12 11:59:24.512050 | controller | Thursday 12 March 2026  11:59:24 +0000 (0:00:00.277)       0:00:01.450 ********
2026-03-12 11:59:24.512060 | controller |
2026-03-12 11:59:24.807366 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:24.807391 | controller | Thursday 12 March 2026  11:59:24 +0000 (0:00:00.025)       0:00:01.475 ********
2026-03-12 11:59:24.807409 | controller | ok: [instance]
2026-03-12 11:59:25.103765 | controller |
2026-03-12 11:59:25.103819 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 11:59:25.103830 | controller | Thursday 12 March 2026  11:59:24 +0000 (0:00:00.294)       0:00:01.770 ********
2026-03-12 11:59:25.103843 | controller | ok: [instance]
2026-03-12 11:59:25.103866 | controller |
2026-03-12 11:59:25.103874 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 11:59:25.103883 | controller | Thursday 12 March 2026  11:59:25 +0000 (0:00:00.296)       0:00:02.066 ********
2026-03-12 11:59:25.405062 | controller | ok: [instance]
2026-03-12 11:59:25.696727 | controller |
2026-03-12 11:59:25.696762 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-03-12 11:59:25.696772 | controller | Thursday 12 March 2026  11:59:25 +0000 (0:00:00.300)       0:00:02.367 ********
2026-03-12 11:59:25.696784 | controller | ok: [instance]
2026-03-12 11:59:25.696805 | controller |
2026-03-12 11:59:25.696813 | controller | TASK [Assert host is now Off] **************************************************
2026-03-12 11:59:25.696822 | controller | Thursday 12 March 2026  11:59:25 +0000 (0:00:00.292)       0:00:02.659 ********
2026-03-12 11:59:25.718688 | controller | ok: [instance] => {
2026-03-12 11:59:25.718757 | controller |     "changed": false,
2026-03-12 11:59:25.718767 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:25.718783 | controller | }
2026-03-12 11:59:25.718802 | controller |
2026-03-12 11:59:25.718812 | controller | TASK [Test bm_power_on] ********************************************************
2026-03-12 11:59:25.743408 | controller | Thursday 12 March 2026  11:59:25 +0000 (0:00:00.021)       0:00:02.681 ********
2026-03-12 11:59:25.743453 | 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 11:59:26.039279 | controller |
2026-03-12 11:59:26.039316 | controller | TASK [Reset mock to power On] **************************************************
2026-03-12 11:59:26.039323 | controller | Thursday 12 March 2026  11:59:25 +0000 (0:00:00.024)       0:00:02.706 ********
2026-03-12 11:59:26.039334 | controller | ok: [instance]
2026-03-12 11:59:26.066320 | controller |
2026-03-12 11:59:26.066340 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-12 11:59:26.066347 | controller | Thursday 12 March 2026  11:59:26 +0000 (0:00:00.295)       0:00:03.001 ********
2026-03-12 11:59:26.066357 | controller |
2026-03-12 11:59:26.365641 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:26.365687 | controller | Thursday 12 March 2026  11:59:26 +0000 (0:00:00.027)       0:00:03.029 ********
2026-03-12 11:59:26.365701 | controller | ok: [instance]
2026-03-12 11:59:26.365730 | controller |
2026-03-12 11:59:26.365739 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 11:59:26.365761 | controller | Thursday 12 March 2026  11:59:26 +0000 (0:00:00.298)       0:00:03.328 ********
2026-03-12 11:59:26.384088 | controller | skipping: [instance]
2026-03-12 11:59:26.701947 | controller |
2026-03-12 11:59:26.701977 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 11:59:26.701986 | controller | Thursday 12 March 2026  11:59:26 +0000 (0:00:00.018)       0:00:03.347 ********
2026-03-12 11:59:26.701996 | controller | ok: [instance]
2026-03-12 11:59:27.011294 | controller |
2026-03-12 11:59:27.011331 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-03-12 11:59:27.011340 | controller | Thursday 12 March 2026  11:59:26 +0000 (0:00:00.317)       0:00:03.664 ********
2026-03-12 11:59:27.011351 | controller | ok: [instance]
2026-03-12 11:59:27.033125 | controller |
2026-03-12 11:59:27.033150 | controller | TASK [Assert host is still On] *************************************************
2026-03-12 11:59:27.033158 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.309)       0:00:03.973 ********
2026-03-12 11:59:27.033168 | controller | ok: [instance] => {
2026-03-12 11:59:27.313573 | controller |     "changed": false,
2026-03-12 11:59:27.313602 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:27.313610 | controller | }
2026-03-12 11:59:27.313621 | controller |
2026-03-12 11:59:27.313627 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-12 11:59:27.313633 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.021)       0:00:03.995 ********
2026-03-12 11:59:27.313643 | controller | ok: [instance]
2026-03-12 11:59:27.340232 | controller |
2026-03-12 11:59:27.340248 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-12 11:59:27.340256 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.280)       0:00:04.276 ********
2026-03-12 11:59:27.340264 | controller |
2026-03-12 11:59:27.630374 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:27.630397 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.026)       0:00:04.303 ********
2026-03-12 11:59:27.630408 | controller | ok: [instance]
2026-03-12 11:59:27.926568 | controller |
2026-03-12 11:59:27.926607 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 11:59:27.926617 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.289)       0:00:04.593 ********
2026-03-12 11:59:27.926629 | controller | ok: [instance]
2026-03-12 11:59:28.218969 | controller |
2026-03-12 11:59:28.219002 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 11:59:28.219010 | controller | Thursday 12 March 2026  11:59:27 +0000 (0:00:00.295)       0:00:04.889 ********
2026-03-12 11:59:28.219020 | controller | ok: [instance]
2026-03-12 11:59:28.501115 | controller |
2026-03-12 11:59:28.501143 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-03-12 11:59:28.501151 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.292)       0:00:05.181 ********
2026-03-12 11:59:28.501162 | controller | ok: [instance]
2026-03-12 11:59:28.522449 | controller |
2026-03-12 11:59:28.522465 | controller | TASK [Assert host is now On] ***************************************************
2026-03-12 11:59:28.522472 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.282)       0:00:05.463 ********
2026-03-12 11:59:28.522480 | controller | ok: [instance] => {
2026-03-12 11:59:28.547305 | controller |     "changed": false,
2026-03-12 11:59:28.547336 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:28.547348 | controller | }
2026-03-12 11:59:28.547357 | controller |
2026-03-12 11:59:28.547367 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-03-12 11:59:28.547377 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.021)       0:00:05.485 ********
2026-03-12 11:59:28.547391 | 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 11:59:28.832108 | controller |
2026-03-12 11:59:28.832149 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-03-12 11:59:28.832157 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.024)       0:00:05.510 ********
2026-03-12 11:59:28.832168 | controller | ok: [instance]
2026-03-12 11:59:28.857386 | controller |
2026-03-12 11:59:28.857402 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-03-12 11:59:28.857409 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.284)       0:00:05.794 ********
2026-03-12 11:59:28.857418 | controller |
2026-03-12 11:59:29.149770 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 11:59:29.149844 | controller | Thursday 12 March 2026  11:59:28 +0000 (0:00:00.025)       0:00:05.820 ********
2026-03-12 11:59:29.149869 | controller | ok: [instance]
2026-03-12 11:59:29.182223 | controller |
2026-03-12 11:59:29.182247 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 11:59:29.182255 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.292)       0:00:06.112 ********
2026-03-12 11:59:29.182265 | controller | ok: [instance]
2026-03-12 11:59:29.212686 | controller |
2026-03-12 11:59:29.212724 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 11:59:29.212733 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.032)       0:00:06.144 ********
2026-03-12 11:59:29.212745 | controller | skipping: [instance]
2026-03-12 11:59:29.212752 | controller |
2026-03-12 11:59:29.212759 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-03-12 11:59:29.212767 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.030)       0:00:06.175 ********
2026-03-12 11:59:29.242672 | controller | ok: [instance] => {
2026-03-12 11:59:29.242713 | controller |     "changed": false,
2026-03-12 11:59:29.242721 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:29.242729 | controller | }
2026-03-12 11:59:29.242738 | controller |
2026-03-12 11:59:29.242983 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-12 11:59:29.526217 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.029)       0:00:06.205 ********
2026-03-12 11:59:29.526240 | controller | ok: [instance]
2026-03-12 11:59:29.551619 | controller |
2026-03-12 11:59:29.551638 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-03-12 11:59:29.551646 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.283)       0:00:06.489 ********
2026-03-12 11:59:29.551657 | controller |
2026-03-12 11:59:29.833037 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 11:59:29.833060 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.025)       0:00:06.514 ********
2026-03-12 11:59:29.833078 | controller | ok: [instance]
2026-03-12 11:59:29.866744 | controller |
2026-03-12 11:59:29.866801 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 11:59:29.866812 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.281)       0:00:06.796 ********
2026-03-12 11:59:29.866835 | controller | ok: [instance]
2026-03-12 11:59:29.866869 | controller |
2026-03-12 11:59:29.866878 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 11:59:29.867001 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.033)       0:00:06.829 ********
2026-03-12 11:59:29.894335 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 11:59:29.899409 | controller |
2026-03-12 11:59:29.920710 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-03-12 11:59:29.920752 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.032)       0:00:06.862 ********
2026-03-12 11:59:29.920768 | controller | ok: [instance] => {
2026-03-12 11:59:29.920776 | controller |     "changed": false,
2026-03-12 11:59:29.920783 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:29.920802 | controller | }
2026-03-12 11:59:29.920810 | controller |
2026-03-12 11:59:29.920817 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-03-12 11:59:29.920826 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.020)       0:00:06.883 ********
2026-03-12 11:59:29.951090 | 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 11:59:30.243611 | controller |
2026-03-12 11:59:30.243633 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-03-12 11:59:30.243641 | controller | Thursday 12 March 2026  11:59:29 +0000 (0:00:00.030)       0:00:06.913 ********
2026-03-12 11:59:30.243651 | controller | ok: [instance]
2026-03-12 11:59:30.276296 | controller |
2026-03-12 11:59:30.276314 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-03-12 11:59:30.276322 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.292)       0:00:07.206 ********
2026-03-12 11:59:30.276330 | controller |
2026-03-12 11:59:30.297760 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 11:59:30.297836 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.032)       0:00:07.239 ********
2026-03-12 11:59:30.297852 | 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 11:59:30.297892 | controller |
2026-03-12 11:59:30.297902 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 11:59:30.298067 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.021)       0:00:07.260 ********
2026-03-12 11:59:30.586756 | controller | ok: [instance]
2026-03-12 11:59:30.621988 | controller |
2026-03-12 11:59:30.622006 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 11:59:30.622014 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.289)       0:00:07.549 ********
2026-03-12 11:59:30.622023 | controller | ok: [instance]
2026-03-12 11:59:30.653745 | controller |
2026-03-12 11:59:30.653800 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 11:59:30.653811 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.035)       0:00:07.584 ********
2026-03-12 11:59:30.653824 | controller | skipping: [instance]
2026-03-12 11:59:30.654070 | controller |
2026-03-12 11:59:30.654088 | controller | TASK [Query mock state] ********************************************************
2026-03-12 11:59:30.654099 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.031)       0:00:07.616 ********
2026-03-12 11:59:30.936385 | controller | ok: [instance]
2026-03-12 11:59:30.962378 | controller |
2026-03-12 11:59:30.962417 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-03-12 11:59:30.962428 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.283)       0:00:07.899 ********
2026-03-12 11:59:30.962441 | controller | ok: [instance] => {
2026-03-12 11:59:31.239295 | controller |     "changed": false,
2026-03-12 11:59:31.239314 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:31.239321 | controller | }
2026-03-12 11:59:31.239327 | controller |
2026-03-12 11:59:31.239333 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-03-12 11:59:31.239338 | controller | Thursday 12 March 2026  11:59:30 +0000 (0:00:00.025)       0:00:07.924 ********
2026-03-12 11:59:31.239353 | controller | ok: [instance]
2026-03-12 11:59:31.269353 | controller |
2026-03-12 11:59:31.269382 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-03-12 11:59:31.269394 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.277)       0:00:08.202 ********
2026-03-12 11:59:31.269410 | controller |
2026-03-12 11:59:31.290310 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 11:59:31.290328 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.029)       0:00:08.232 ********
2026-03-12 11:59:31.290338 | 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 11:59:31.572254 | controller |
2026-03-12 11:59:31.572274 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 11:59:31.572288 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.020)       0:00:08.253 ********
2026-03-12 11:59:31.572298 | controller | ok: [instance]
2026-03-12 11:59:31.604638 | controller |
2026-03-12 11:59:31.604675 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 11:59:31.604683 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.281)       0:00:08.535 ********
2026-03-12 11:59:31.604694 | controller | ok: [instance]
2026-03-12 11:59:31.629729 | controller |
2026-03-12 11:59:31.629751 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 11:59:31.629759 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.032)       0:00:08.567 ********
2026-03-12 11:59:31.629768 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 11:59:31.634670 | controller |
2026-03-12 11:59:31.634738 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-12 11:59:31.634893 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.030)       0:00:08.597 ********
2026-03-12 11:59:31.664285 | controller | skipping: [instance]
2026-03-12 11:59:31.961713 | controller |
2026-03-12 11:59:31.961752 | controller | TASK [reproducer : Set GenericUsbBoot BIOS attribute] **************************
2026-03-12 11:59:31.961762 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.029)       0:00:08.627 ********
2026-03-12 11:59:31.961776 | controller | ok: [instance]
2026-03-12 11:59:31.961814 | controller |
2026-03-12 11:59:31.961825 | controller | TASK [reproducer : Create BIOS config job to schedule the change] **************
2026-03-12 11:59:32.243627 | controller | Thursday 12 March 2026  11:59:31 +0000 (0:00:00.297)       0:00:08.924 ********
2026-03-12 11:59:32.243659 | controller | ok: [instance]
2026-03-12 11:59:32.268114 | controller |
2026-03-12 11:59:32.268134 | controller | TASK [reproducer : Power off before applying BIOS change] **********************
2026-03-12 11:59:32.268142 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.281)       0:00:09.206 ********
2026-03-12 11:59:32.268152 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-12 11:59:32.550429 | controller |
2026-03-12 11:59:32.550451 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:32.550459 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.024)       0:00:09.231 ********
2026-03-12 11:59:32.550468 | controller | ok: [instance]
2026-03-12 11:59:32.568050 | controller |
2026-03-12 11:59:32.568070 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 11:59:32.568079 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.282)       0:00:09.513 ********
2026-03-12 11:59:32.568091 | controller | skipping: [instance]
2026-03-12 11:59:32.585083 | controller |
2026-03-12 11:59:32.585104 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 11:59:32.585113 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.017)       0:00:09.530 ********
2026-03-12 11:59:32.585125 | controller | skipping: [instance]
2026-03-12 11:59:32.609224 | controller |
2026-03-12 11:59:32.609243 | controller | TASK [reproducer : Power on to apply BIOS config job during POST] **************
2026-03-12 11:59:32.609261 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.017)       0:00:09.548 ********
2026-03-12 11:59:32.609274 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_on.yml for instance
2026-03-12 11:59:32.898127 | controller |
2026-03-12 11:59:32.898163 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:32.898171 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.024)       0:00:09.572 ********
2026-03-12 11:59:32.898182 | controller | ok: [instance]
2026-03-12 11:59:33.183047 | controller |
2026-03-12 11:59:33.183079 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-12 11:59:33.183087 | controller | Thursday 12 March 2026  11:59:32 +0000 (0:00:00.288)       0:00:09.860 ********
2026-03-12 11:59:33.183099 | controller | ok: [instance]
2026-03-12 11:59:33.465077 | controller |
2026-03-12 11:59:33.465110 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-12 11:59:33.465118 | controller | Thursday 12 March 2026  11:59:33 +0000 (0:00:00.284)       0:00:10.144 ********
2026-03-12 11:59:33.465129 | controller | ok: [instance]
2026-03-12 11:59:33.492433 | controller |
2026-03-12 11:59:33.492458 | controller | TASK [reproducer : Power off after BIOS change applied] ************************
2026-03-12 11:59:33.492466 | controller | Thursday 12 March 2026  11:59:33 +0000 (0:00:00.282)       0:00:10.427 ********
2026-03-12 11:59:33.492477 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-12 11:59:33.782056 | controller |
2026-03-12 11:59:33.782085 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-12 11:59:33.782092 | controller | Thursday 12 March 2026  11:59:33 +0000 (0:00:00.027)       0:00:10.455 ********
2026-03-12 11:59:33.782110 | controller | ok: [instance]
2026-03-12 11:59:34.075702 | controller |
2026-03-12 11:59:34.075744 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-12 11:59:34.075754 | controller | Thursday 12 March 2026  11:59:33 +0000 (0:00:00.289)       0:00:10.744 ********
2026-03-12 11:59:34.075767 | controller | ok: [instance]
2026-03-12 11:59:34.075809 | controller |
2026-03-12 11:59:34.075820 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-12 11:59:34.371009 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.293)       0:00:11.038 ********
2026-03-12 11:59:34.371053 | controller | ok: [instance]
2026-03-12 11:59:34.655495 | controller |
2026-03-12 11:59:34.655524 | controller | TASK [Query mock state after auto-enable] **************************************
2026-03-12 11:59:34.655532 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.295)       0:00:11.333 ********
2026-03-12 11:59:34.655558 | controller | ok: [instance]
2026-03-12 11:59:34.677690 | controller |
2026-03-12 11:59:34.677736 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-03-12 11:59:34.677747 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.284)       0:00:11.618 ********
2026-03-12 11:59:34.677761 | controller | ok: [instance] => {
2026-03-12 11:59:34.677811 | controller |     "changed": false,
2026-03-12 11:59:34.677824 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:34.677853 | controller | }
2026-03-12 11:59:34.678204 | controller |
2026-03-12 11:59:34.960568 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-12 11:59:34.960603 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.022)       0:00:11.640 ********
2026-03-12 11:59:34.960615 | controller | ok: [instance]
2026-03-12 11:59:34.989328 | controller |
2026-03-12 11:59:34.989354 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-03-12 11:59:34.989365 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.282)       0:00:11.923 ********
2026-03-12 11:59:34.989379 | controller |
2026-03-12 11:59:35.009659 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-12 11:59:35.009801 | controller | Thursday 12 March 2026  11:59:34 +0000 (0:00:00.028)       0:00:11.952 ********
2026-03-12 11:59:35.009825 | 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 11:59:35.009918 | controller |
2026-03-12 11:59:35.291078 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-12 11:59:35.291101 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.020)       0:00:11.972 ********
2026-03-12 11:59:35.291114 | controller | ok: [instance]
2026-03-12 11:59:35.322508 | controller |
2026-03-12 11:59:35.322529 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-12 11:59:35.322538 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.281)       0:00:12.254 ********
2026-03-12 11:59:35.322573 | controller | ok: [instance]
2026-03-12 11:59:35.348920 | controller |
2026-03-12 11:59:35.348941 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-12 11:59:35.348950 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.031)       0:00:12.285 ********
2026-03-12 11:59:35.348961 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-12 11:59:35.353997 | controller |
2026-03-12 11:59:35.381509 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-12 11:59:35.381529 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.031)       0:00:12.317 ********
2026-03-12 11:59:35.381560 | 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 11:59:35.386471 | controller |
2026-03-12 11:59:35.408677 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-03-12 11:59:35.408735 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.032)       0:00:12.349 ********
2026-03-12 11:59:35.408759 | controller | ok: [instance] => {
2026-03-12 11:59:35.438672 | controller |     "changed": false,
2026-03-12 11:59:35.438704 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:35.438718 | controller | }
2026-03-12 11:59:35.438727 | controller |
2026-03-12 11:59:35.438737 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-03-12 11:59:35.438746 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.021)       0:00:12.371 ********
2026-03-12 11:59:35.438761 | 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 11:59:35.438898 | controller |
2026-03-12 11:59:35.438914 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 11:59:35.439015 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.030)       0:00:12.401 ********
2026-03-12 11:59:35.734131 | controller | ok: [instance]
2026-03-12 11:59:35.759123 | controller |
2026-03-12 11:59:35.759155 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-03-12 11:59:35.759168 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.294)       0:00:12.696 ********
2026-03-12 11:59:35.759183 | controller |
2026-03-12 11:59:36.054970 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-12 11:59:36.055015 | controller | Thursday 12 March 2026  11:59:35 +0000 (0:00:00.025)       0:00:12.722 ********
2026-03-12 11:59:36.055027 | controller | ok: [instance]
2026-03-12 11:59:41.083759 | controller |
2026-03-12 11:59:41.083813 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-12 11:59:41.083821 | controller | Thursday 12 March 2026  11:59:36 +0000 (0:00:00.295)       0:00:13.017 ********
2026-03-12 11:59:41.083834 | controller | Pausing for 5 seconds
2026-03-12 11:59:41.083858 | controller | ok: [instance]
2026-03-12 11:59:41.083864 | controller |
2026-03-12 11:59:41.083872 | controller | TASK [Query mock state after eject] ********************************************
2026-03-12 11:59:41.083895 | controller | Thursday 12 March 2026  11:59:41 +0000 (0:00:05.028)       0:00:18.046 ********
2026-03-12 11:59:41.376668 | controller | ok: [instance]
2026-03-12 11:59:41.376763 | controller |
2026-03-12 11:59:41.376925 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-03-12 11:59:41.376967 | controller | Thursday 12 March 2026  11:59:41 +0000 (0:00:00.293)       0:00:18.339 ********
2026-03-12 11:59:41.406765 | controller | ok: [instance] => {
2026-03-12 11:59:41.407274 | controller |     "changed": false,
2026-03-12 11:59:41.407293 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:41.407305 | controller | }
2026-03-12 11:59:41.692280 | controller |
2026-03-12 11:59:41.692322 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-03-12 11:59:41.692331 | controller | Thursday 12 March 2026  11:59:41 +0000 (0:00:00.029)       0:00:18.369 ********
2026-03-12 11:59:41.692344 | controller | ok: [instance]
2026-03-12 11:59:41.716723 | controller |
2026-03-12 11:59:41.716758 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-03-12 11:59:41.716768 | controller | Thursday 12 March 2026  11:59:41 +0000 (0:00:00.285)       0:00:18.654 ********
2026-03-12 11:59:41.716793 | controller |
2026-03-12 11:59:41.716862 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-12 11:59:41.716883 | controller | Thursday 12 March 2026  11:59:41 +0000 (0:00:00.024)       0:00:18.679 ********
2026-03-12 11:59:42.007655 | controller | ok: [instance]
2026-03-12 11:59:42.007691 | controller |
2026-03-12 11:59:42.007699 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-12 11:59:42.007707 | controller | Thursday 12 March 2026  11:59:42 +0000 (0:00:00.290)       0:00:18.970 ********
2026-03-12 11:59:47.036713 | controller | Pausing for 5 seconds
2026-03-12 11:59:47.325531 | controller | ok: [instance]
2026-03-12 11:59:47.325583 | controller |
2026-03-12 11:59:47.325592 | controller | TASK [Query mock state] ********************************************************
2026-03-12 11:59:47.325598 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:05.028)       0:00:23.999 ********
2026-03-12 11:59:47.325609 | controller | ok: [instance]
2026-03-12 11:59:47.356323 | controller |
2026-03-12 11:59:47.356342 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-03-12 11:59:47.356351 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:00.289)       0:00:24.288 ********
2026-03-12 11:59:47.356361 | controller | ok: [instance] => {
2026-03-12 11:59:47.390180 | controller |     "changed": false,
2026-03-12 11:59:47.390201 | controller |     "msg": "All assertions passed"
2026-03-12 11:59:47.390210 | controller | }
2026-03-12 11:59:47.390217 | controller |
2026-03-12 11:59:47.390224 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-03-12 11:59:47.390231 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:00.030)       0:00:24.318 ********
2026-03-12 11:59:47.390242 | 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 11:59:47.680532 | controller |
2026-03-12 11:59:47.680569 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 11:59:47.680577 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:00.034)       0:00:24.353 ********
2026-03-12 11:59:47.680586 | controller | ok: [instance]
2026-03-12 11:59:47.715600 | controller |
2026-03-12 11:59:47.715632 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-03-12 11:59:47.715645 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:00.290)       0:00:24.643 ********
2026-03-12 11:59:47.715661 | controller |
2026-03-12 11:59:48.009178 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 11:59:48.009203 | controller | Thursday 12 March 2026  11:59:47 +0000 (0:00:00.034)       0:00:24.678 ********
2026-03-12 11:59:48.009216 | controller | ok: [instance]
2026-03-12 11:59:49.454735 | controller |
2026-03-12 11:59:49.454782 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 11:59:49.454792 | controller | Thursday 12 March 2026  11:59:48 +0000 (0:00:00.293)       0:00:24.971 ********
2026-03-12 11:59:49.454805 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 11:59:49.454838 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 11:59:49.454848 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 11:59:49.454876 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 11:59:49.455294 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 11:59:49.493927 | controller |
2026-03-12 11:59:49.493947 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 11:59:49.493962 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:01.445)       0:00:26.417 ********
2026-03-12 11:59:49.493978 | controller | ok: [instance]
2026-03-12 11:59:49.517244 | controller |
2026-03-12 11:59:49.517262 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 11:59:49.517270 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.039)       0:00:26.456 ********
2026-03-12 11:59:49.517279 | controller | skipping: [instance]
2026-03-12 11:59:49.583693 | controller |
2026-03-12 11:59:49.583731 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-12 11:59:49.583739 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.023)       0:00:26.479 ********
2026-03-12 11:59:49.583751 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-12 11:59:49.605506 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-12 11:59:49.605531 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-03-12 11:59:49.605560 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-12 11:59:49.605572 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-12 11:59:49.605578 | controller |
2026-03-12 11:59:49.605586 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-12 11:59:49.605593 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.066)       0:00:26.546 ********
2026-03-12 11:59:49.605605 | controller | skipping: [instance]
2026-03-12 11:59:49.625710 | controller |
2026-03-12 11:59:49.625756 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-12 11:59:49.625778 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.022)       0:00:26.568 ********
2026-03-12 11:59:49.625794 | controller | ok: [instance] => {
2026-03-12 11:59:49.625902 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-12 11:59:49.625915 | controller | }
2026-03-12 11:59:49.625926 | controller |
2026-03-12 11:59:49.626018 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-12 11:59:49.626130 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.020)       0:00:26.588 ********
2026-03-12 11:59:49.923323 | controller | ok: [instance]
2026-03-12 11:59:59.953720 | controller |
2026-03-12 11:59:59.953800 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-12 11:59:59.953810 | controller | Thursday 12 March 2026  11:59:49 +0000 (0:00:00.297)       0:00:26.886 ********
2026-03-12 11:59:59.953830 | controller | Pausing for 10 seconds
2026-03-12 11:59:59.953886 | controller | ok: [instance]
2026-03-12 11:59:59.953895 | controller |
2026-03-12 11:59:59.953904 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-12 12:00:00.248672 | controller | Thursday 12 March 2026  11:59:59 +0000 (0:00:10.030)       0:00:36.916 ********
2026-03-12 12:00:00.248723 | controller | ok: [instance]
2026-03-12 12:00:00.566233 | controller |
2026-03-12 12:00:00.566271 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-12 12:00:00.566279 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.295)       0:00:37.211 ********
2026-03-12 12:00:00.566290 | controller | ok: [instance]
2026-03-12 12:00:00.591704 | controller |
2026-03-12 12:00:00.591762 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-12 12:00:00.591773 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.317)       0:00:37.529 ********
2026-03-12 12:00:00.591798 | controller | ok: [instance] => {
2026-03-12 12:00:00.898186 | controller |     "changed": false,
2026-03-12 12:00:00.898218 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:00.898227 | controller | }
2026-03-12 12:00:00.898233 | controller |
2026-03-12 12:00:00.898239 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-12 12:00:00.898245 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.025)       0:00:37.554 ********
2026-03-12 12:00:00.898255 | controller | ok: [instance]
2026-03-12 12:00:00.939319 | controller |
2026-03-12 12:00:00.939349 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-12 12:00:00.939364 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.306)       0:00:37.861 ********
2026-03-12 12:00:00.939375 | controller | ok: [instance] => {
2026-03-12 12:00:00.977282 | controller |     "changed": false,
2026-03-12 12:00:00.977309 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:00.977316 | controller | }
2026-03-12 12:00:00.977322 | controller |
2026-03-12 12:00:00.977328 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-03-12 12:00:00.977334 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.040)       0:00:37.902 ********
2026-03-12 12:00:00.977345 | controller | ok: [instance] => {
2026-03-12 12:00:01.282554 | controller |     "changed": false,
2026-03-12 12:00:01.282578 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:01.282586 | controller | }
2026-03-12 12:00:01.282592 | controller |
2026-03-12 12:00:01.282598 | controller | TASK [Query mock state after discover] *****************************************
2026-03-12 12:00:01.282603 | controller | Thursday 12 March 2026  12:00:00 +0000 (0:00:00.037)       0:00:37.939 ********
2026-03-12 12:00:01.282612 | controller | ok: [instance]
2026-03-12 12:00:01.314510 | controller |
2026-03-12 12:00:01.314535 | controller | TASK [Assert boot override was set] ********************************************
2026-03-12 12:00:01.314560 | controller | Thursday 12 March 2026  12:00:01 +0000 (0:00:00.305)       0:00:38.245 ********
2026-03-12 12:00:01.314573 | controller | ok: [instance] => {
2026-03-12 12:00:01.628741 | controller |     "changed": false,
2026-03-12 12:00:01.628794 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:01.628804 | controller | }
2026-03-12 12:00:01.628811 | controller |
2026-03-12 12:00:01.628819 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 12:00:01.628826 | controller | Thursday 12 March 2026  12:00:01 +0000 (0:00:00.031)       0:00:38.277 ********
2026-03-12 12:00:01.628849 | controller | ok: [instance]
2026-03-12 12:00:01.664197 | controller |
2026-03-12 12:00:01.664237 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-03-12 12:00:01.664247 | controller | Thursday 12 March 2026  12:00:01 +0000 (0:00:00.314)       0:00:38.591 ********
2026-03-12 12:00:01.664259 | controller |
2026-03-12 12:00:01.987425 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 12:00:01.987461 | controller | Thursday 12 March 2026  12:00:01 +0000 (0:00:00.035)       0:00:38.627 ********
2026-03-12 12:00:01.987473 | controller | ok: [instance]
2026-03-12 12:00:03.410736 | controller |
2026-03-12 12:00:03.410808 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 12:00:03.410820 | controller | Thursday 12 March 2026  12:00:01 +0000 (0:00:00.323)       0:00:38.950 ********
2026-03-12 12:00:03.410837 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 12:00:03.410880 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 12:00:03.410889 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 12:00:03.410896 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 12:00:03.410904 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 12:00:03.410911 | controller |
2026-03-12 12:00:03.410921 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 12:00:03.451092 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:01.422)       0:00:40.372 ********
2026-03-12 12:00:03.451148 | controller | ok: [instance]
2026-03-12 12:00:03.492428 | controller |
2026-03-12 12:00:03.492453 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 12:00:03.492462 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.041)       0:00:40.414 ********
2026-03-12 12:00:03.492472 | controller | ok: [instance] => {
2026-03-12 12:00:03.550692 | controller |     "changed": false,
2026-03-12 12:00:03.550739 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:03.550760 | controller | }
2026-03-12 12:00:03.550768 | controller |
2026-03-12 12:00:03.550776 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-12 12:00:03.550783 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.040)       0:00:40.455 ********
2026-03-12 12:00:03.550798 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-12 12:00:03.550830 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-12 12:00:03.550839 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-03-12 12:00:03.550853 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-12 12:00:03.550862 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-12 12:00:03.550872 | controller | skipping: [instance]
2026-03-12 12:00:03.551063 | controller |
2026-03-12 12:00:03.551086 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-12 12:00:03.573038 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.058)       0:00:40.513 ********
2026-03-12 12:00:03.573066 | controller | skipping: [instance]
2026-03-12 12:00:03.573232 | controller |
2026-03-12 12:00:03.573404 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-12 12:00:03.573587 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.023)       0:00:40.536 ********
2026-03-12 12:00:03.593963 | controller | ok: [instance] => {
2026-03-12 12:00:03.594196 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-12 12:00:03.594329 | controller | }
2026-03-12 12:00:03.594451 | controller |
2026-03-12 12:00:03.594607 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-12 12:00:03.594751 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.020)       0:00:40.557 ********
2026-03-12 12:00:03.894385 | controller | ok: [instance]
2026-03-12 12:00:13.927351 | controller |
2026-03-12 12:00:13.927385 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-12 12:00:13.927393 | controller | Thursday 12 March 2026  12:00:03 +0000 (0:00:00.299)       0:00:40.857 ********
2026-03-12 12:00:13.927403 | controller | Pausing for 10 seconds
2026-03-12 12:00:14.213704 | controller | ok: [instance]
2026-03-12 12:00:14.213760 | controller |
2026-03-12 12:00:14.213771 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-12 12:00:14.213779 | controller | Thursday 12 March 2026  12:00:13 +0000 (0:00:10.032)       0:00:50.889 ********
2026-03-12 12:00:14.213794 | controller | ok: [instance]
2026-03-12 12:00:14.213842 | controller |
2026-03-12 12:00:14.213869 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-12 12:00:14.213878 | controller | Thursday 12 March 2026  12:00:14 +0000 (0:00:00.287)       0:00:51.176 ********
2026-03-12 12:00:14.503754 | controller | ok: [instance]
2026-03-12 12:00:14.530281 | controller |
2026-03-12 12:00:14.530310 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-12 12:00:14.530318 | controller | Thursday 12 March 2026  12:00:14 +0000 (0:00:00.289)       0:00:51.466 ********
2026-03-12 12:00:14.530328 | controller | ok: [instance] => {
2026-03-12 12:00:14.812769 | controller |     "changed": false,
2026-03-12 12:00:14.812815 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:14.812829 | controller | }
2026-03-12 12:00:14.812840 | controller |
2026-03-12 12:00:14.812850 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-12 12:00:14.812860 | controller | Thursday 12 March 2026  12:00:14 +0000 (0:00:00.026)       0:00:51.492 ********
2026-03-12 12:00:14.812877 | controller | ok: [instance]
2026-03-12 12:00:14.849475 | controller |
2026-03-12 12:00:14.849514 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-12 12:00:14.849522 | controller | Thursday 12 March 2026  12:00:14 +0000 (0:00:00.282)       0:00:51.775 ********
2026-03-12 12:00:14.849553 | controller | ok: [instance] => {
2026-03-12 12:00:15.129357 | controller |     "changed": false,
2026-03-12 12:00:15.129389 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:15.129398 | controller | }
2026-03-12 12:00:15.129404 | controller |
2026-03-12 12:00:15.129410 | controller | TASK [Query mock state] ********************************************************
2026-03-12 12:00:15.129416 | controller | Thursday 12 March 2026  12:00:14 +0000 (0:00:00.036)       0:00:51.812 ********
2026-03-12 12:00:15.129426 | controller | ok: [instance]
2026-03-12 12:00:15.149596 | controller |
2026-03-12 12:00:15.149615 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-03-12 12:00:15.149622 | controller | Thursday 12 March 2026  12:00:15 +0000 (0:00:00.280)       0:00:52.092 ********
2026-03-12 12:00:15.149631 | controller | ok: [instance] => {
2026-03-12 12:00:15.149652 | controller |     "changed": false,
2026-03-12 12:00:15.149665 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:15.149671 | controller | }
2026-03-12 12:00:15.149676 | controller |
2026-03-12 12:00:15.149683 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-12 12:00:15.149740 | controller | Thursday 12 March 2026  12:00:15 +0000 (0:00:00.020)       0:00:52.112 ********
2026-03-12 12:00:15.429091 | controller | ok: [instance]
2026-03-12 12:00:15.459367 | controller |
2026-03-12 12:00:15.459395 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-03-12 12:00:15.459405 | controller | Thursday 12 March 2026  12:00:15 +0000 (0:00:00.279)       0:00:52.391 ********
2026-03-12 12:00:15.459416 | controller |
2026-03-12 12:00:15.738409 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-12 12:00:15.738442 | controller | Thursday 12 March 2026  12:00:15 +0000 (0:00:00.030)       0:00:52.422 ********
2026-03-12 12:00:15.738454 | controller | ok: [instance]
2026-03-12 12:00:17.097743 | controller |
2026-03-12 12:00:17.097785 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-12 12:00:17.097795 | controller | Thursday 12 March 2026  12:00:15 +0000 (0:00:00.278)       0:00:52.701 ********
2026-03-12 12:00:17.097808 | controller | ok: [instance] => (item=Boot0001)
2026-03-12 12:00:17.097840 | controller | ok: [instance] => (item=Boot0003)
2026-03-12 12:00:17.097847 | controller | ok: [instance] => (item=Boot0004)
2026-03-12 12:00:17.097854 | controller | ok: [instance] => (item=Boot0005)
2026-03-12 12:00:17.097863 | controller | ok: [instance] => (item=Boot0006)
2026-03-12 12:00:17.098144 | controller |
2026-03-12 12:00:17.136609 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-12 12:00:17.136650 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:01.359)       0:00:54.060 ********
2026-03-12 12:00:17.136665 | controller | ok: [instance]
2026-03-12 12:00:17.173626 | controller |
2026-03-12 12:00:17.173649 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-12 12:00:17.173657 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:00.038)       0:00:54.099 ********
2026-03-12 12:00:17.173667 | controller | fatal: [instance]: FAILED! => {
2026-03-12 12:00:17.173691 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-03-12 12:00:17.173698 | controller |     "changed": false,
2026-03-12 12:00:17.173703 | controller |     "evaluated_to": false,
2026-03-12 12:00:17.173709 | 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 12:00:17.173718 | controller | }
2026-03-12 12:00:17.178080 | controller |
2026-03-12 12:00:17.220671 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-03-12 12:00:17.220695 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:00.041)       0:00:54.141 ********
2026-03-12 12:00:17.220707 | controller | ok: [instance] => {
2026-03-12 12:00:17.220853 | controller |     "changed": false,
2026-03-12 12:00:17.220863 | controller |     "msg": "All assertions passed"
2026-03-12 12:00:17.220870 | controller | }
2026-03-12 12:00:17.220876 | controller |
2026-03-12 12:00:17.220884 | controller | PLAY RECAP *********************************************************************
2026-03-12 12:00:17.220891 | controller | instance                   : ok=110  changed=0    unreachable=0    failed=0    skipped=12   rescued=5    ignored=0
2026-03-12 12:00:17.220898 | controller |
2026-03-12 12:00:17.220905 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:00.041)       0:00:54.182 ********
2026-03-12 12:00:17.220911 | controller | ===============================================================================
2026-03-12 12:00:17.220918 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-12 12:00:17.220930 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-12 12:00:17.220941 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-12 12:00:17.221060 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-12 12:00:17.221073 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.45s
2026-03-12 12:00:17.221167 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.42s
2026-03-12 12:00:17.221271 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.36s
2026-03-12 12:00:17.221367 | controller | Reset mock to power Off ------------------------------------------------- 0.41s
2026-03-12 12:00:17.221475 | controller | reproducer : Fetch UEFI boot option IDs --------------------------------- 0.32s
2026-03-12 12:00:17.221607 | controller | reproducer : Verify boot override was applied --------------------------- 0.32s
2026-03-12 12:00:17.221732 | controller | reproducer : Wait for host POST to complete ----------------------------- 0.32s
2026-03-12 12:00:17.221830 | controller | Reset mock with VirtualMedia inserted ----------------------------------- 0.31s
2026-03-12 12:00:17.221930 | controller | Query mock state after power_on (already on) ---------------------------- 0.31s
2026-03-12 12:00:17.222037 | controller | reproducer : Verify VirtualMedia is still inserted ---------------------- 0.31s
2026-03-12 12:00:17.222145 | controller | Query mock state after discover ----------------------------------------- 0.31s
2026-03-12 12:00:17.222250 | controller | reproducer : Wait for host to power off --------------------------------- 0.30s
2026-03-12 12:00:17.222354 | controller | reproducer : Clear pending iDRAC config jobs that block boot override --- 0.30s
2026-03-12 12:00:17.222456 | controller | reproducer : Query current power state ---------------------------------- 0.30s
2026-03-12 12:00:17.222574 | controller | reproducer : Set GenericUsbBoot BIOS attribute -------------------------- 0.30s
2026-03-12 12:00:17.222688 | controller | reproducer : Clear pending iDRAC config jobs that block boot override --- 0.30s
2026-03-12 12:00:17.285323 | controller | INFO     Running bm_redfish > cleanup
2026-03-12 12:00:17.697689 | controller |
2026-03-12 12:00:17.697856 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-12 12:00:17.697971 | controller |
2026-03-12 12:00:17.698083 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-12 12:00:17.698192 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:00.026)       0:00:00.026 ********
2026-03-12 12:00:17.996953 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.014953", "end": "2026-03-12 12:00:17.972421", "msg": "non-zero return code", "rc": -15, "start": "2026-03-12 12:00:17.957468", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-12 12:00:17.999491 | controller |
2026-03-12 12:00:18.073664 | controller | PLAY RECAP *********************************************************************
2026-03-12 12:00:18.073716 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-12 12:00:18.073740 | controller |
2026-03-12 12:00:18.073747 | controller | Thursday 12 March 2026  12:00:17 +0000 (0:00:00.302)       0:00:00.329 ********
2026-03-12 12:00:18.073752 | controller | ===============================================================================
2026-03-12 12:00:18.073758 | controller | Stop mock iDRAC server -------------------------------------------------- 0.30s
2026-03-12 12:00:18.073774 | 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 12:00:18.073901 | controller | WARNING  An error occurred during the test sequence action: 'cleanup'. Cleaning up.
2026-03-12 12:00:18.083346 | controller | INFO     Running bm_redfish > cleanup
2026-03-12 12:00:18.488395 | controller |
2026-03-12 12:00:18.488539 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-12 12:00:18.488671 | controller |
2026-03-12 12:00:18.488808 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-12 12:00:18.488940 | controller | Thursday 12 March 2026  12:00:18 +0000 (0:00:00.023)       0:00:00.023 ********
2026-03-12 12:00:18.778787 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.013866", "end": "2026-03-12 12:00:18.755310", "msg": "non-zero return code", "rc": -15, "start": "2026-03-12 12:00:18.741444", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-12 12:00:18.780773 | controller |
2026-03-12 12:00:18.780861 | controller | PLAY RECAP *********************************************************************
2026-03-12 12:00:18.780879 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-12 12:00:18.780889 | controller |
2026-03-12 12:00:18.780899 | controller | Thursday 12 March 2026  12:00:18 +0000 (0:00:00.293)       0:00:00.316 ********
2026-03-12 12:00:18.780914 | controller | ===============================================================================
2026-03-12 12:00:18.832355 | controller | Stop mock iDRAC server -------------------------------------------------- 0.29s
2026-03-12 12:00:18.832384 | 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 12:00:18.833076 | controller | INFO     Writing /tmp/report.html report.
2026-03-12 12:00:19.093598 | controller | ERROR
2026-03-12 12:00:19.093791 | controller | {
2026-03-12 12:00:19.093828 | controller |   "delta": "0:00:59.996800",
2026-03-12 12:00:19.093851 | controller |   "end": "2026-03-12 12:00:18.888672",
2026-03-12 12:00:19.093871 | controller |   "msg": "non-zero return code",
2026-03-12 12:00:19.093888 | controller |   "rc": 2,
2026-03-12 12:00:19.093919 | controller |   "start": "2026-03-12 11:59:18.891872"
2026-03-12 12:00:19.093937 | controller | }
failure
2026-03-12 12:00:19.139408 | 
2026-03-12 12:00:19.139458 | PLAY RECAP
2026-03-12 12:00:19.139498 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2026-03-12 12:00:19.139519 | 
2026-03-12 12:00:19.206022 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-12 12:00:19.206875 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-12 12:00:19.743159 | 
2026-03-12 12:00:19.743259 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-03-12 12:00:19.762627 | 
2026-03-12 12:00:19.762699 | TASK [Filter out host if needed]
2026-03-12 12:00:19.771076 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-03-12 12:00:19.775401 | 
2026-03-12 12:00:19.775469 | TASK [Ensure file is present]
2026-03-12 12:00:20.140620 | controller | ok
2026-03-12 12:00:20.146352 | 
2026-03-12 12:00:20.146422 | TASK [Manage molecule report file]
2026-03-12 12:00:20.673201 | controller | changed
2026-03-12 12:00:20.679207 | 
2026-03-12 12:00:20.679282 | TASK [Check if we get ci-framework-data basedir]
2026-03-12 12:00:20.928031 | controller | ok
2026-03-12 12:00:20.933756 | 
2026-03-12 12:00:20.933832 | TASK [Create ci-framework-data log directory for zuul]
2026-03-12 12:00:21.310415 | controller | changed
2026-03-12 12:00:21.315700 | 
2026-03-12 12:00:21.315770 | TASK [Copy ci-framework interesting files]
2026-03-12 12:00:21.572106 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-03-12 12:00:21.842369 | controller | changed
2026-03-12 12:00:21.847662 | 
2026-03-12 12:00:21.847734 | TASK [Get SELinux listing]
2026-03-12 12:00:22.375801 | controller | changed
2026-03-12 12:00:22.381360 | 
2026-03-12 12:00:22.381432 | TASK [Generate log index]
2026-03-12 12:00:23.477986 | controller | changed
2026-03-12 12:00:23.482948 | 
2026-03-12 12:00:23.483012 | TASK [Get some env related data]
2026-03-12 12:00:24.136024 | controller | /home/zuul/.local/bin/ansible
2026-03-12 12:00:25.012368 | controller | changed
2026-03-12 12:00:25.020101 | 
2026-03-12 12:00:25.020198 | TASK [Generate list of logs to collect in home directory]
2026-03-12 12:00:25.419358 | controller | ok: All paths examined
2026-03-12 12:00:25.424462 | 
2026-03-12 12:00:25.424522 | LOOP [Copy logs from home directory]
2026-03-12 12:00:26.087110 | controller | changed:
2026-03-12 12:00:26.087388 | controller | {
2026-03-12 12:00:26.087420 | controller |   "atime": 1772005405.932821,
2026-03-12 12:00:26.087440 | controller |   "ctime": 1772006396.9238591,
2026-03-12 12:00:26.087457 | controller |   "dev": 64513,
2026-03-12 12:00:26.087482 | controller |   "gid": 1000,
2026-03-12 12:00:26.087498 | controller |   "gr_name": "zuul",
2026-03-12 12:00:26.087515 | controller |   "inode": 2773,
2026-03-12 12:00:26.087531 | controller |   "isblk": false,
2026-03-12 12:00:26.087546 | controller |   "ischr": false,
2026-03-12 12:00:26.087561 | controller |   "isdir": false,
2026-03-12 12:00:26.087575 | controller |   "isfifo": false,
2026-03-12 12:00:26.087589 | controller |   "isgid": false,
2026-03-12 12:00:26.087602 | controller |   "islnk": false,
2026-03-12 12:00:26.087615 | controller |   "isreg": true,
2026-03-12 12:00:26.087628 | controller |   "issock": false,
2026-03-12 12:00:26.087641 | controller |   "isuid": false,
2026-03-12 12:00:26.087654 | controller |   "mode": "0644",
2026-03-12 12:00:26.087667 | controller |   "mtime": 1772006396.9238591,
2026-03-12 12:00:26.087680 | controller |   "nlink": 1,
2026-03-12 12:00:26.087694 | controller |   "path": "/home/zuul/crc-setup.log",
2026-03-12 12:00:26.087715 | controller |   "pw_name": "zuul",
2026-03-12 12:00:26.087731 | controller |   "rgrp": true,
2026-03-12 12:00:26.087745 | controller |   "roth": true,
2026-03-12 12:00:26.087759 | controller |   "rusr": true,
2026-03-12 12:00:26.087773 | controller |   "size": 4108,
2026-03-12 12:00:26.087909 | controller |   "uid": 1000,
2026-03-12 12:00:26.088025 | controller |   "wgrp": false,
2026-03-12 12:00:26.088051 | controller |   "woth": false,
2026-03-12 12:00:26.088072 | controller |   "wusr": true,
2026-03-12 12:00:26.088097 | controller |   "xgrp": false,
2026-03-12 12:00:26.088114 | controller |   "xoth": false,
2026-03-12 12:00:26.088129 | controller |   "xusr": false
2026-03-12 12:00:26.088144 | controller | }
2026-03-12 12:00:26.712008 | controller | changed:
2026-03-12 12:00:26.712140 | controller | {
2026-03-12 12:00:26.712438 | controller |   "atime": 1772006398.6759083,
2026-03-12 12:00:26.712479 | controller |   "ctime": 1772007098.5537844,
2026-03-12 12:00:26.712504 | controller |   "dev": 64513,
2026-03-12 12:00:26.712531 | controller |   "gid": 1000,
2026-03-12 12:00:26.712549 | controller |   "gr_name": "zuul",
2026-03-12 12:00:26.712566 | controller |   "inode": 359205,
2026-03-12 12:00:26.712583 | controller |   "isblk": false,
2026-03-12 12:00:26.712599 | controller |   "ischr": false,
2026-03-12 12:00:26.712614 | controller |   "isdir": false,
2026-03-12 12:00:26.712628 | controller |   "isfifo": false,
2026-03-12 12:00:26.712707 | controller |   "isgid": false,
2026-03-12 12:00:26.712739 | controller |   "islnk": false,
2026-03-12 12:00:26.712759 | controller |   "isreg": true,
2026-03-12 12:00:26.712777 | controller |   "issock": false,
2026-03-12 12:00:26.712802 | controller |   "isuid": false,
2026-03-12 12:00:26.712818 | controller |   "mode": "0644",
2026-03-12 12:00:26.712833 | controller |   "mtime": 1772007098.5537844,
2026-03-12 12:00:26.712848 | controller |   "nlink": 1,
2026-03-12 12:00:26.712864 | controller |   "path": "/home/zuul/crc-start.log",
2026-03-12 12:00:26.712880 | controller |   "pw_name": "zuul",
2026-03-12 12:00:26.712903 | controller |   "rgrp": true,
2026-03-12 12:00:26.712921 | controller |   "roth": true,
2026-03-12 12:00:26.712938 | controller |   "rusr": true,
2026-03-12 12:00:26.712954 | controller |   "size": 4654,
2026-03-12 12:00:26.712971 | controller |   "uid": 1000,
2026-03-12 12:00:26.712986 | controller |   "wgrp": false,
2026-03-12 12:00:26.713002 | controller |   "woth": false,
2026-03-12 12:00:26.713016 | controller |   "wusr": true,
2026-03-12 12:00:26.713030 | controller |   "xgrp": false,
2026-03-12 12:00:26.713043 | controller |   "xoth": false,
2026-03-12 12:00:26.713057 | controller |   "xusr": false
2026-03-12 12:00:26.713071 | controller | }
2026-03-12 12:00:27.312557 | controller | changed:
2026-03-12 12:00:27.312673 | controller | {
2026-03-12 12:00:27.312699 | controller |   "atime": 1773316740.1863577,
2026-03-12 12:00:27.312718 | controller |   "ctime": 1773316756.2663128,
2026-03-12 12:00:27.312735 | controller |   "dev": 64513,
2026-03-12 12:00:27.312758 | controller |   "gid": 1000,
2026-03-12 12:00:27.312775 | controller |   "gr_name": "zuul",
2026-03-12 12:00:27.312790 | controller |   "inode": 1189030,
2026-03-12 12:00:27.312805 | controller |   "isblk": false,
2026-03-12 12:00:27.312819 | controller |   "ischr": false,
2026-03-12 12:00:27.312834 | controller |   "isdir": false,
2026-03-12 12:00:27.312847 | controller |   "isfifo": false,
2026-03-12 12:00:27.312860 | controller |   "isgid": false,
2026-03-12 12:00:27.312873 | controller |   "islnk": false,
2026-03-12 12:00:27.312887 | controller |   "isreg": true,
2026-03-12 12:00:27.312911 | controller |   "issock": false,
2026-03-12 12:00:27.312926 | controller |   "isuid": false,
2026-03-12 12:00:27.312940 | controller |   "mode": "0644",
2026-03-12 12:00:27.312954 | controller |   "mtime": 1773316756.2663128,
2026-03-12 12:00:27.312967 | controller |   "nlink": 1,
2026-03-12 12:00:27.312982 | controller |   "path": "/home/zuul/ansible.log",
2026-03-12 12:00:27.312996 | controller |   "pw_name": "zuul",
2026-03-12 12:00:27.313011 | controller |   "rgrp": true,
2026-03-12 12:00:27.313025 | controller |   "roth": true,
2026-03-12 12:00:27.313041 | controller |   "rusr": true,
2026-03-12 12:00:27.313056 | controller |   "size": 6749,
2026-03-12 12:00:27.313070 | controller |   "uid": 1000,
2026-03-12 12:00:27.313083 | controller |   "wgrp": false,
2026-03-12 12:00:27.313097 | controller |   "woth": false,
2026-03-12 12:00:27.313110 | controller |   "wusr": true,
2026-03-12 12:00:27.313123 | controller |   "xgrp": false,
2026-03-12 12:00:27.313138 | controller |   "xoth": false,
2026-03-12 12:00:27.313152 | controller |   "xusr": false
2026-03-12 12:00:27.313166 | controller | }
2026-03-12 12:00:27.326693 | 
2026-03-12 12:00:27.326902 | TASK [Copy crio stats log file]
2026-03-12 12:00:27.352983 | controller | skipping: Conditional result was False
2026-03-12 12:00:27.358680 | 
2026-03-12 12:00:27.358747 | TASK [Get SELinux related data]
2026-03-12 12:00:27.659105 | controller | <no matches>
2026-03-12 12:00:27.887855 | controller | ERROR
2026-03-12 12:00:27.888072 | controller | {
2026-03-12 12:00:27.888102 | controller |   "delta": "0:00:00.011317",
2026-03-12 12:00:27.888123 | controller |   "end": "2026-03-12 12:00:27.659838",
2026-03-12 12:00:27.888141 | controller |   "msg": "non-zero return code",
2026-03-12 12:00:27.888156 | controller |   "rc": 1,
2026-03-12 12:00:27.888171 | controller |   "start": "2026-03-12 12:00:27.648521"
2026-03-12 12:00:27.888186 | controller | }
2026-03-12 12:00:27.888207 | controller | ERROR: Ignoring Errors
2026-03-12 12:00:27.893070 | 
2026-03-12 12:00:27.893131 | TASK [Create system configuration directory]
2026-03-12 12:00:28.167840 | controller | changed
2026-03-12 12:00:28.181683 | 
2026-03-12 12:00:28.181987 | TASK [Get some of the system configurations]
2026-03-12 12:00:28.709873 | controller | changed
2026-03-12 12:00:28.715601 | 
2026-03-12 12:00:28.715666 | TASK [Copy generated documentation if available]
2026-03-12 12:00:28.729905 | controller | skipping: Conditional result was False
2026-03-12 12:00:28.735620 | 
2026-03-12 12:00:28.735680 | TASK [Copy generated AsciiDoc documentation if available]
2026-03-12 12:00:28.749479 | controller | skipping: Conditional result was False
2026-03-12 12:00:28.754967 | 
2026-03-12 12:00:28.755030 | TASK [Compress logs bigger than 2MB]
2026-03-12 12:00:29.282951 | controller | changed
2026-03-12 12:00:29.288130 | 
2026-03-12 12:00:29.288196 | TASK [Copy files from workspace on node]
2026-03-12 12:00:29.307369 | controller | ok
2026-03-12 12:00:29.331807 | 
2026-03-12 12:00:29.331877 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-12 12:00:29.358210 | controller | skipping: Conditional result was False
2026-03-12 12:00:29.372102 | 
2026-03-12 12:00:29.372178 | TASK [fetch-output : Set log path for single node]
2026-03-12 12:00:29.402159 | controller | ok
2026-03-12 12:00:29.407007 | 
2026-03-12 12:00:29.407073 | LOOP [fetch-output : Ensure local output dirs]
2026-03-12 12:00:29.606380 | controller -> localhost | ok: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/logs"
2026-03-12 12:00:29.606756 | controller -> localhost | changed: All items complete
2026-03-12 12:00:29.606786 | 
2026-03-12 12:00:29.800788 | controller -> localhost | changed: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/artifacts"
2026-03-12 12:00:29.994516 | controller -> localhost | changed: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/docs"
2026-03-12 12:00:30.007221 | 
2026-03-12 12:00:30.007310 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-12 12:00:30.654581 | controller | changed:
2026-03-12 12:00:30.654844 | controller | .d..t...... ./
2026-03-12 12:00:30.654875 | controller | >f+++++++++ README.html
2026-03-12 12:00:30.654909 | controller | >f+++++++++ ansible-execution.log
2026-03-12 12:00:30.654935 | controller | >f+++++++++ ansible.log
2026-03-12 12:00:30.654958 | controller | >f+++++++++ crc-setup.log
2026-03-12 12:00:30.654979 | controller | >f+++++++++ crc-start.log
2026-03-12 12:00:30.654998 | controller | >f+++++++++ dmesg.log
2026-03-12 12:00:30.655018 | controller | >f+++++++++ installed-pkgs.log
2026-03-12 12:00:30.655036 | controller | >f+++++++++ python.log
2026-03-12 12:00:30.655053 | controller | >f+++++++++ registries.conf
2026-03-12 12:00:30.655070 | controller | >f+++++++++ report.html
2026-03-12 12:00:30.655088 | controller | >f+++++++++ selinux-denials.log
2026-03-12 12:00:30.655105 | controller | >f+++++++++ selinux-listing.log
2026-03-12 12:00:30.655122 | controller | cd+++++++++ ci-framework-data/
2026-03-12 12:00:30.655138 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-03-12 12:00:30.655156 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-03-12 12:00:30.655173 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-03-12 12:00:30.655189 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-03-12 12:00:30.655206 | controller | cd+++++++++ ci-framework-data/logs/
2026-03-12 12:00:30.655222 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-03-12 12:00:30.655237 | controller | cd+++++++++ registries.conf.d/
2026-03-12 12:00:30.655253 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-03-12 12:00:30.655270 | controller | cd+++++++++ system-config/
2026-03-12 12:00:30.655287 | controller | cd+++++++++ system-config/libvirt/
2026-03-12 12:00:30.655330 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-03-12 12:00:30.655352 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-03-12 12:00:30.655370 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2026-03-12 12:00:30.655386 | controller | >f+++++++++ system-config/libvirt/network.conf
2026-03-12 12:00:30.655403 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2026-03-12 12:00:30.655419 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2026-03-12 12:00:30.655436 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2026-03-12 12:00:30.655452 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2026-03-12 12:00:30.655468 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2026-03-12 12:00:30.655486 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2026-03-12 12:00:30.655503 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2026-03-12 12:00:30.655518 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2026-03-12 12:00:30.655534 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2026-03-12 12:00:30.655550 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2026-03-12 12:00:30.655565 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2026-03-12 12:00:30.655580 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2026-03-12 12:00:31.128598 | controller | changed: .d..t...... ./
2026-03-12 12:00:31.628205 | controller | changed: .d..t...... ./
2026-03-12 12:00:31.648906 | 
2026-03-12 12:00:31.649018 | TASK [Return artifact to Zuul]
2026-03-12 12:00:31.689642 | controller | ok
2026-03-12 12:00:31.709519 | 
2026-03-12 12:00:31.709579 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-03-12 12:00:31.709690 | 
2026-03-12 12:00:31.709718 | PLAY RECAP
2026-03-12 12:00:31.709761 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-03-12 12:00:31.709783 | 
2026-03-12 12:00:31.805258 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-12 12:00:31.806103 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-12 12:00:32.322903 | 
2026-03-12 12:00:32.323058 | PLAY [all]
2026-03-12 12:00:32.340869 | 
2026-03-12 12:00:32.340953 | TASK [include_role : fetch-output]
2026-03-12 12:00:32.370254 | controller | ok
2026-03-12 12:00:32.386955 | 
2026-03-12 12:00:32.387112 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-12 12:00:32.431063 | controller | skipping: Conditional result was False
2026-03-12 12:00:32.436569 | 
2026-03-12 12:00:32.436648 | TASK [fetch-output : Set log path for single node]
2026-03-12 12:00:32.464559 | controller | ok
2026-03-12 12:00:32.469529 | 
2026-03-12 12:00:32.469601 | LOOP [fetch-output : Ensure local output dirs]
2026-03-12 12:00:32.787483 | controller -> localhost | ok: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/logs"
2026-03-12 12:00:32.973779 | controller -> localhost | ok: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/artifacts"
2026-03-12 12:00:33.160930 | controller -> localhost | ok: "/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/docs"
2026-03-12 12:00:33.168834 | 
2026-03-12 12:00:33.168915 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-12 12:00:33.795510 | controller | ok
2026-03-12 12:00:33.795711 | controller | ok: All items complete
2026-03-12 12:00:33.795740 | 
2026-03-12 12:00:34.255161 | controller | ok
2026-03-12 12:00:34.705884 | controller | ok
2026-03-12 12:00:34.725469 | 
2026-03-12 12:00:34.725544 | TASK [include_role : fetch-output-openshift]
2026-03-12 12:00:34.750500 | controller | skipping: Conditional result was False
2026-03-12 12:00:34.756323 | 
2026-03-12 12:00:34.756397 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-03-12 12:00:35.113725 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.007672
2026-03-12 12:00:35.301633 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007532
2026-03-12 12:00:35.332001 | 
2026-03-12 12:00:35.332061 | PLAY [all]
2026-03-12 12:00:35.345369 | 
2026-03-12 12:00:35.345435 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-03-12 12:00:35.842243 | controller | changed
2026-03-12 12:00:35.863706 | 
2026-03-12 12:00:35.863761 | PLAY RECAP
2026-03-12 12:00:35.863806 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-03-12 12:00:35.863951 | 
2026-03-12 12:00:35.939227 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-12 12:00:35.939981 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-03-12 12:00:36.502105 | 
2026-03-12 12:00:36.502312 | PLAY [localhost]
2026-03-12 12:00:36.518935 | 
2026-03-12 12:00:36.519007 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-03-12 12:00:36.832902 | localhost | changed
2026-03-12 12:00:36.837327 | 
2026-03-12 12:00:36.837416 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-03-12 12:00:36.867031 | localhost | ok
2026-03-12 12:00:36.874341 | 
2026-03-12 12:00:36.874410 | TASK [add-fileserver : Create SSH private key tempfile]
2026-03-12 12:00:37.178019 | localhost | changed
2026-03-12 12:00:37.184341 | 
2026-03-12 12:00:37.184417 | TASK [add-fileserver : Create SSH private key from secret]
2026-03-12 12:00:37.731255 | localhost | changed
2026-03-12 12:00:37.736877 | 
2026-03-12 12:00:37.736980 | TASK [add-fileserver : Add fileserver ssh key]
2026-03-12 12:00:38.087652 | localhost | Identity added: /var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/tmp/ansible.tn7jei3w (/var/lib/zuul/builds/d3a5949a26c648c1942a9be4304559e1/work/tmp/ansible.tn7jei3w)
2026-03-12 12:00:38.087837 | localhost | ok: Runtime: 0:00:00.008260
2026-03-12 12:00:38.092017 | 
2026-03-12 12:00:38.092093 | TASK [add-fileserver : Remove SSH private key from disk]
2026-03-12 12:00:38.312574 | localhost | ok: Runtime: 0:00:00.005338
2026-03-12 12:00:38.317260 | 
2026-03-12 12:00:38.317369 | TASK [add-fileserver : Add fileserver to inventory]
2026-03-12 12:00:38.365707 | localhost | changed
2026-03-12 12:00:38.370962 | 
2026-03-12 12:00:38.371033 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-03-12 12:00:38.713556 | localhost | changed
2026-03-12 12:00:38.733801 | 
2026-03-12 12:00:38.733876 | PLAY [localhost]
2026-03-12 12:00:38.745620 | 
2026-03-12 12:00:38.745687 | TASK [Generate bulk log download script]
2026-03-12 12:00:38.766226 | localhost | ok
2026-03-12 12:00:38.777986 | 
2026-03-12 12:00:38.778065 | TASK [local-log-download : Check API endpoint is defined]
2026-03-12 12:00:38.805396 | localhost | ok: All assertions passed
2026-03-12 12:00:38.809881 | 
2026-03-12 12:00:38.809967 | TASK [local-log-download : Create download script]
2026-03-12 12:00:39.167470 | localhost -> localhost | changed
2026-03-12 12:00:39.175803 | 
2026-03-12 12:00:39.175881 | TASK [Register quick-download link]
2026-03-12 12:00:39.203383 | localhost | ok
2026-03-12 12:00:39.248434 | 
2026-03-12 12:00:39.248517 | PLAY [logserver.rdoproject.org]
2026-03-12 12:00:39.257194 | 
2026-03-12 12:00:39.257255 | TASK [Set zuul-log-path fact]
2026-03-12 12:00:39.274722 | logserver.rdoproject.org | ok
2026-03-12 12:00:39.283967 | 
2026-03-12 12:00:39.284045 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-12 12:00:39.311343 | logserver.rdoproject.org | ok
2026-03-12 12:00:39.316855 | 
2026-03-12 12:00:39.316931 | TASK [upload-logs : Create log directories]
2026-03-12 12:00:41.036861 | logserver.rdoproject.org | changed
2026-03-12 12:00:41.040026 | 
2026-03-12 12:00:41.040089 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-03-12 12:00:41.255810 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005244
2026-03-12 12:00:41.260258 | 
2026-03-12 12:00:41.260337 | TASK [upload-logs : Upload logs to log server]
2026-03-12 12:00:42.677215 | logserver.rdoproject.org | Output suppressed because no_log was given
2026-03-12 12:00:42.680444 | 
2026-03-12 12:00:42.680521 | LOOP [upload-logs : Compress console log and json output]
2026-03-12 12:00:42.723409 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 12:00:42.731687 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 12:00:42.740824 | 
2026-03-12 12:00:42.740963 | LOOP [upload-logs : Upload compressed console log and json output]
2026-03-12 12:00:42.781485 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 12:00:42.781780 | 
2026-03-12 12:00:42.784603 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-12 12:00:42.790205 | 
2026-03-12 12:00:42.790353 | LOOP [upload-logs : Upload console log and json output]