2026-03-13 10:08:38.041080 | Job console starting...
2026-03-13 10:08:38.249479 | Updating repositories
2026-03-13 10:08:38.271441 | Preparing job workspace
2026-03-13 10:08:45.114124 | Running Ansible setup...
2026-03-13 10:08:48.554566 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-13 10:08:49.039845 | 
2026-03-13 10:08:49.039975 | PLAY [localhost]
2026-03-13 10:08:49.047700 | 
2026-03-13 10:08:49.047765 | TASK [Gathering Facts]
2026-03-13 10:08:49.821819 | localhost | ok
2026-03-13 10:08:49.835462 | 
2026-03-13 10:08:49.835546 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-03-13 10:08:50.133476 | localhost -> localhost | changed
2026-03-13 10:08:50.138473 | 
2026-03-13 10:08:50.138539 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-03-13 10:08:50.789199 | localhost -> localhost | changed
2026-03-13 10:08:50.797387 | 
2026-03-13 10:08:50.797465 | TASK [Setup log path fact]
2026-03-13 10:08:50.814433 | localhost | ok
2026-03-13 10:08:50.825377 | 
2026-03-13 10:08:50.825450 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-13 10:08:50.842440 | localhost | ok
2026-03-13 10:08:50.849604 | 
2026-03-13 10:08:50.849697 | TASK [emit-job-header : Print job information]
2026-03-13 10:08:50.875936 | # Job Information
2026-03-13 10:08:50.876050 | Ansible Version: 2.15.12
2026-03-13 10:08:50.876078 | Job: cifmw-molecule-reproducer
2026-03-13 10:08:50.876100 | Pipeline: github-check
2026-03-13 10:08:50.876120 | Executor: ibm-bm4-ze.softwarefactory-project.io
2026-03-13 10:08:50.876139 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3739
2026-03-13 10:08:50.876159 | Log URL (when completed): https://logserver.rdoproject.org/df9/rdoproject.org/df938b3a65c64cca900875da078e3a19/
2026-03-13 10:08:50.876177 | Event ID: 764458d0-1ec4-11f1-8d3e-94f36f4b371b
2026-03-13 10:08:50.879855 | 
2026-03-13 10:08:50.879918 | LOOP [emit-job-header : Print node information]
2026-03-13 10:08:50.959773 | localhost | ok:
2026-03-13 10:08:50.959885 | localhost | # Node Information
2026-03-13 10:08:50.959913 | localhost | Inventory Hostname: controller
2026-03-13 10:08:50.959936 | localhost | Hostname: np0005646118
2026-03-13 10:08:50.959956 | localhost | Username: zuul
2026-03-13 10:08:50.959975 | localhost | Distro: CentOS 9
2026-03-13 10:08:50.959993 | localhost | Provider: ibm-bm4-nodepool
2026-03-13 10:08:50.960010 | localhost | Region: regionOne
2026-03-13 10:08:50.960026 | localhost | Label: centos-9-stream-crc-2-48-0-xxl-ibm
2026-03-13 10:08:50.960042 | localhost | Product Name: OpenStack Compute
2026-03-13 10:08:50.960058 | localhost | Interface IP: 192.168.26.126
2026-03-13 10:08:50.980221 | 
2026-03-13 10:08:50.980273 | PLAY [all]
2026-03-13 10:08:50.985942 | 
2026-03-13 10:08:50.986000 | TASK [Gather network facts]
2026-03-13 10:08:51.399186 | controller | ok
2026-03-13 10:08:51.413212 | 
2026-03-13 10:08:51.413272 | TASK [include_role : start-zuul-console]
2026-03-13 10:08:51.430262 | controller | ok
2026-03-13 10:08:51.441118 | 
2026-03-13 10:08:51.441175 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-03-13 10:08:51.813611 | controller | ok
2026-03-13 10:08:51.820979 | 
2026-03-13 10:08:51.821038 | TASK [include_role : add-build-sshkey]
2026-03-13 10:08:51.837909 | controller | ok
2026-03-13 10:08:51.849284 | 
2026-03-13 10:08:51.849368 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-03-13 10:08:52.035332 | controller -> localhost | ok
2026-03-13 10:08:52.040405 | 
2026-03-13 10:08:52.040472 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-03-13 10:08:52.057665 | controller | ok
2026-03-13 10:08:52.070751 | controller | included: /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-03-13 10:08:52.075818 | 
2026-03-13 10:08:52.075882 | TASK [add-build-sshkey : Create Temp SSH key]
2026-03-13 10:08:52.688682 | controller -> localhost | Generating public/private rsa key pair.
2026-03-13 10:08:52.688851 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/df938b3a65c64cca900875da078e3a19_id_rsa.
2026-03-13 10:08:52.688884 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/df938b3a65c64cca900875da078e3a19_id_rsa.pub.
2026-03-13 10:08:52.688907 | controller -> localhost | The key fingerprint is:
2026-03-13 10:08:52.688927 | controller -> localhost | SHA256:QXDYXc0yaZ+8HR6BFYvFUcO5FEyl/7cAKKSsN/ntk54 zuul-build-sshkey
2026-03-13 10:08:52.688947 | controller -> localhost | The key's randomart image is:
2026-03-13 10:08:52.688965 | controller -> localhost | +---[RSA 3072]----+
2026-03-13 10:08:52.688982 | controller -> localhost | |      .+o. ..+BOX|
2026-03-13 10:08:52.688999 | controller -> localhost | |      .o. . =.=Oo|
2026-03-13 10:08:52.689017 | controller -> localhost | |       ..  . *ooo|
2026-03-13 10:08:52.689035 | controller -> localhost | |    . o  ..   += |
2026-03-13 10:08:52.689052 | controller -> localhost | |     o .S. .  .o+|
2026-03-13 10:08:52.689069 | controller -> localhost | |    . . .   . ..o|
2026-03-13 10:08:52.689086 | controller -> localhost | |   . +    .  .  o|
2026-03-13 10:08:52.689106 | controller -> localhost | |    . o .o.   . o|
2026-03-13 10:08:52.689123 | controller -> localhost | |       .oE.    . |
2026-03-13 10:08:52.689139 | controller -> localhost | +----[SHA256]-----+
2026-03-13 10:08:52.689177 | controller -> localhost | ok: Runtime: 0:00:00.298601
2026-03-13 10:08:52.694288 | 
2026-03-13 10:08:52.694375 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-03-13 10:08:52.720531 | controller | ok
2026-03-13 10:08:52.728933 | controller | included: /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-03-13 10:08:52.736035 | 
2026-03-13 10:08:52.736099 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-03-13 10:08:52.749686 | controller | skipping: Conditional result was False
2026-03-13 10:08:52.754933 | 
2026-03-13 10:08:52.754997 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-03-13 10:08:53.209023 | controller | changed
2026-03-13 10:08:53.213219 | 
2026-03-13 10:08:53.213279 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-03-13 10:08:53.465216 | controller | ok
2026-03-13 10:08:53.469626 | 
2026-03-13 10:08:53.469684 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-03-13 10:08:54.610748 | controller | changed
2026-03-13 10:08:54.615494 | 
2026-03-13 10:08:54.615563 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-03-13 10:08:55.761538 | controller | changed
2026-03-13 10:08:55.765935 | 
2026-03-13 10:08:55.765994 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-03-13 10:08:55.779118 | controller | skipping: Conditional result was False
2026-03-13 10:08:55.783910 | 
2026-03-13 10:08:55.783971 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-03-13 10:08:56.050526 | controller -> localhost | changed
2026-03-13 10:08:56.059319 | 
2026-03-13 10:08:56.059391 | TASK [add-build-sshkey : Add back temp key]
2026-03-13 10:08:56.265073 | controller -> localhost | Identity added: /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/df938b3a65c64cca900875da078e3a19_id_rsa (zuul-build-sshkey)
2026-03-13 10:08:56.265281 | controller -> localhost | ok: Runtime: 0:00:00.006485
2026-03-13 10:08:56.270793 | 
2026-03-13 10:08:56.270854 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-03-13 10:08:56.611821 | controller | ok
2026-03-13 10:08:56.616651 | 
2026-03-13 10:08:56.616709 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-03-13 10:08:56.639935 | controller | skipping: Conditional result was False
2026-03-13 10:08:56.648063 | 
2026-03-13 10:08:56.648121 | TASK [include_role : validate-host]
2026-03-13 10:08:56.665152 | controller | ok
2026-03-13 10:08:56.682095 | 
2026-03-13 10:08:56.682155 | TASK [validate-host : Define zuul_info_dir fact]
2026-03-13 10:08:56.710211 | controller | ok
2026-03-13 10:08:56.714494 | 
2026-03-13 10:08:56.714562 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-03-13 10:08:56.900134 | controller -> localhost | ok
2026-03-13 10:08:56.905089 | 
2026-03-13 10:08:56.905146 | TASK [validate-host : Collect information about the host]
2026-03-13 10:08:57.592749 | controller | ok
2026-03-13 10:08:57.600048 | 
2026-03-13 10:08:57.600119 | TASK [validate-host : Sanitize hostname]
2026-03-13 10:08:57.637872 | controller | ok
2026-03-13 10:08:57.642260 | 
2026-03-13 10:08:57.642343 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-03-13 10:08:57.990072 | controller -> localhost | changed
2026-03-13 10:08:57.995310 | 
2026-03-13 10:08:57.995384 | TASK [validate-host : Collect information about zuul worker]
2026-03-13 10:08:58.368741 | controller | ok
2026-03-13 10:08:58.373279 | 
2026-03-13 10:08:58.373382 | TASK [validate-host : Write out all zuul information for each host]
2026-03-13 10:08:58.712696 | controller -> localhost | changed
2026-03-13 10:08:58.721220 | 
2026-03-13 10:08:58.721284 | TASK [include_role : prepare-workspace-openshift]
2026-03-13 10:08:58.734699 | controller | skipping: Conditional result was False
2026-03-13 10:08:58.739131 | 
2026-03-13 10:08:58.739189 | TASK [include_role : remove-zuul-sshkey]
2026-03-13 10:08:58.752385 | controller | skipping: Conditional result was False
2026-03-13 10:08:58.756776 | 
2026-03-13 10:08:58.756843 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-03-13 10:08:59.021937 | controller | ok: "logs"
2026-03-13 10:08:59.022155 | controller | ok: All items complete
2026-03-13 10:08:59.022183 | 
2026-03-13 10:08:59.250989 | controller | ok: "artifacts"
2026-03-13 10:08:59.482629 | controller | ok: "docs"
2026-03-13 10:08:59.497203 | 
2026-03-13 10:08:59.497315 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-03-13 10:08:59.761547 | controller | changed: "logs"
2026-03-13 10:09:00.004440 | controller | changed: "artifacts"
2026-03-13 10:09:00.235506 | controller | changed: "docs"
2026-03-13 10:09:00.260625 | 
2026-03-13 10:09:00.260704 | PLAY RECAP
2026-03-13 10:09:00.260745 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-13 10:09:00.260770 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-13 10:09:00.260787 | 
2026-03-13 10:09:00.330809 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-03-13 10:09:00.331468 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-13 10:09:00.841632 | 
2026-03-13 10:09:00.841757 | PLAY [all]
2026-03-13 10:09:00.859578 | 
2026-03-13 10:09:00.859650 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-13 10:09:00.908014 | controller | ok
2026-03-13 10:09:00.912626 | 
2026-03-13 10:09:00.912730 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-13 10:09:01.317200 | controller | changed
2026-03-13 10:09:01.322259 | 
2026-03-13 10:09:01.322346 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-13 10:09:02.617200 | controller | changed
2026-03-13 10:09:02.626156 | 
2026-03-13 10:09:02.626231 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-03-13 10:09:03.040776 | controller | changed:
2026-03-13 10:09:03.040924 | controller | {
2026-03-13 10:09:03.040955 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-03-13 10:09:03.040981 | controller | }
2026-03-13 10:09:03.323755 | controller | changed:
2026-03-13 10:09:03.323804 | controller | {
2026-03-13 10:09:03.323831 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-03-13 10:09:03.323851 | controller | }
2026-03-13 10:09:03.607932 | controller | changed:
2026-03-13 10:09:03.607985 | controller | {
2026-03-13 10:09:03.608010 | 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-13 10:09:03.608029 | controller | }
2026-03-13 10:09:03.885820 | controller | changed:
2026-03-13 10:09:03.885870 | controller | {
2026-03-13 10:09:03.885895 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-03-13 10:09:03.885913 | controller | }
2026-03-13 10:09:04.162973 | controller | changed:
2026-03-13 10:09:04.163049 | controller | {
2026-03-13 10:09:04.163078 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-03-13 10:09:04.163099 | controller | }
2026-03-13 10:09:04.442533 | controller | changed:
2026-03-13 10:09:04.442587 | controller | {
2026-03-13 10:09:04.442613 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-03-13 10:09:04.442632 | controller | }
2026-03-13 10:09:04.725068 | controller | changed:
2026-03-13 10:09:04.725127 | controller | {
2026-03-13 10:09:04.725152 | 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-13 10:09:04.725173 | controller | }
2026-03-13 10:09:05.008544 | controller | changed:
2026-03-13 10:09:05.008601 | controller | {
2026-03-13 10:09:05.008628 | 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-13 10:09:05.008648 | controller | }
2026-03-13 10:09:05.308333 | controller | changed:
2026-03-13 10:09:05.308597 | controller | {
2026-03-13 10:09:05.308629 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-03-13 10:09:05.308692 | controller | }
2026-03-13 10:09:05.597672 | controller | changed:
2026-03-13 10:09:05.597748 | controller | {
2026-03-13 10:09:05.597775 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-03-13 10:09:05.597795 | controller | }
2026-03-13 10:09:05.862941 | controller | changed:
2026-03-13 10:09:05.863018 | controller | {
2026-03-13 10:09:05.863042 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-03-13 10:09:05.863061 | controller | }
2026-03-13 10:09:06.144062 | controller | changed:
2026-03-13 10:09:06.144151 | controller | {
2026-03-13 10:09:06.144177 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-03-13 10:09:06.144197 | controller | }
2026-03-13 10:09:06.429519 | controller | changed:
2026-03-13 10:09:06.429584 | controller | {
2026-03-13 10:09:06.429612 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICWBreHW95Wz2Toz5YwCGQwFcUG8oFYkienDh9tntmDc ralfieri@redhat.com"
2026-03-13 10:09:06.429634 | controller | }
2026-03-13 10:09:06.707023 | controller | changed:
2026-03-13 10:09:06.707072 | controller | {
2026-03-13 10:09:06.707095 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-03-13 10:09:06.707113 | controller | }
2026-03-13 10:09:06.986549 | controller | changed:
2026-03-13 10:09:06.986599 | controller | {
2026-03-13 10:09:06.986623 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-03-13 10:09:06.986642 | controller | }
2026-03-13 10:09:07.270498 | controller | changed:
2026-03-13 10:09:07.270658 | controller | {
2026-03-13 10:09:07.270692 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-03-13 10:09:07.270712 | controller | }
2026-03-13 10:09:07.556846 | controller | changed:
2026-03-13 10:09:07.556893 | controller | {
2026-03-13 10:09:07.556918 | 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-13 10:09:07.556937 | controller | }
2026-03-13 10:09:07.841332 | controller | changed:
2026-03-13 10:09:07.841393 | controller | {
2026-03-13 10:09:07.841418 | 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-13 10:09:07.841444 | controller | }
2026-03-13 10:09:08.124988 | controller | changed:
2026-03-13 10:09:08.125041 | controller | {
2026-03-13 10:09:08.125066 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-03-13 10:09:08.125086 | controller | }
2026-03-13 10:09:08.406863 | controller | changed:
2026-03-13 10:09:08.406922 | controller | {
2026-03-13 10:09:08.406946 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-03-13 10:09:08.406965 | controller | }
2026-03-13 10:09:08.693069 | controller | changed:
2026-03-13 10:09:08.693144 | controller | {
2026-03-13 10:09:08.693169 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-03-13 10:09:08.693188 | controller | }
2026-03-13 10:09:09.003899 | controller | changed:
2026-03-13 10:09:09.003962 | controller | {
2026-03-13 10:09:09.003993 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-03-13 10:09:09.004017 | controller | }
2026-03-13 10:09:09.296557 | controller | changed:
2026-03-13 10:09:09.296658 | controller | {
2026-03-13 10:09:09.296683 | 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-13 10:09:09.296704 | controller | }
2026-03-13 10:09:09.577093 | controller | changed:
2026-03-13 10:09:09.577172 | controller | {
2026-03-13 10:09:09.577197 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-03-13 10:09:09.577217 | controller | }
2026-03-13 10:09:09.858434 | controller | changed:
2026-03-13 10:09:09.858495 | controller | {
2026-03-13 10:09:09.858522 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-03-13 10:09:09.858541 | controller | }
2026-03-13 10:09:10.137485 | controller | changed:
2026-03-13 10:09:10.137569 | controller | {
2026-03-13 10:09:10.137595 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-03-13 10:09:10.137614 | controller | }
2026-03-13 10:09:10.152714 | 
2026-03-13 10:09:10.152803 | TASK [Set timezone to UTC]
2026-03-13 10:09:10.616643 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-03-13 10:09:10.621289 | 
2026-03-13 10:09:10.621392 | TASK [Create nodepool directory]
2026-03-13 10:09:10.892534 | controller | changed
2026-03-13 10:09:10.898560 | 
2026-03-13 10:09:10.898625 | TASK [Create nodepool sub_nodes file]
2026-03-13 10:09:11.858405 | controller | changed
2026-03-13 10:09:11.862835 | 
2026-03-13 10:09:11.862902 | TASK [Create nodepool sub_nodes_private file]
2026-03-13 10:09:12.801291 | controller | changed
2026-03-13 10:09:12.806269 | 
2026-03-13 10:09:12.806363 | LOOP [Populate nodepool sub_nodes file]
2026-03-13 10:09:12.835041 | 
2026-03-13 10:09:12.835157 | LOOP [Populate nodepool sub_nodes_private file]
2026-03-13 10:09:12.863130 | 
2026-03-13 10:09:12.863250 | TASK [Create nodepool primary file]
2026-03-13 10:09:12.886464 | controller | skipping: Conditional result was False
2026-03-13 10:09:12.891520 | 
2026-03-13 10:09:12.891591 | TASK [Create nodepool node_private for this node]
2026-03-13 10:09:13.892806 | controller | changed
2026-03-13 10:09:13.900411 | 
2026-03-13 10:09:13.900478 | LOOP [Copy ssh keys to nodepool directory]
2026-03-13 10:09:14.387492 | controller | ok: Item: id_rsa Runtime: 0:00:00.004933
2026-03-13 10:09:14.387669 | 
2026-03-13 10:09:14.611483 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005669
2026-03-13 10:09:14.616996 | 
2026-03-13 10:09:14.617064 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-03-13 10:09:15.557565 | controller | changed
2026-03-13 10:09:15.562042 | 
2026-03-13 10:09:15.562101 | TASK [Validate sudoers config after edits]
2026-03-13 10:09:15.828145 | controller | /etc/sudoers: parsed OK
2026-03-13 10:09:15.828211 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-03-13 10:09:15.828221 | controller | /etc/sudoers.d/zuul: parsed OK
2026-03-13 10:09:15.828228 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-03-13 10:09:16.087695 | controller | ok: Runtime: 0:00:00.005056
2026-03-13 10:09:16.092540 | 
2026-03-13 10:09:16.092596 | TASK [Show the environment passed in to job shell scripts]
2026-03-13 10:09:16.350968 | controller | SHELL=/bin/bash
2026-03-13 10:09:16.351007 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-03-13 10:09:16.351016 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-03-13 10:09:16.351024 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/39/3739/49aced80d27e9606127d64e941573b745d7c8bde
2026-03-13 10:09:16.351030 | controller | PWD=/home/zuul
2026-03-13 10:09:16.351048 | controller | ZUUL_PIPELINE=github-check
2026-03-13 10:09:16.351053 | controller | LOGNAME=zuul
2026-03-13 10:09:16.351059 | controller | XDG_SESSION_TYPE=tty
2026-03-13 10:09:16.351064 | controller | _=/usr/bin/env
2026-03-13 10:09:16.351069 | controller | MOTD_SHOWN=pam
2026-03-13 10:09:16.351075 | controller | HOME=/home/zuul
2026-03-13 10:09:16.351108 | controller | LANG=en_US.UTF-8
2026-03-13 10:09:16.351127 | controller | SSH_CONNECTION=192.168.26.12 34728 192.168.26.126 22
2026-03-13 10:09:16.351137 | 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-13 10:09:16.351145 | controller | ZUUL_CHANGE_IDS=3739,49aced80d27e9606127d64e941573b745d7c8bde
2026-03-13 10:09:16.351151 | controller | WORKSPACE=/home/zuul/workspace
2026-03-13 10:09:16.351156 | controller | XDG_SESSION_CLASS=user
2026-03-13 10:09:16.351162 | controller | SELINUX_ROLE_REQUESTED=
2026-03-13 10:09:16.351167 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-03-13 10:09:16.351172 | controller | USER=zuul
2026-03-13 10:09:16.351178 | controller | ZUUL_VOTING=True
2026-03-13 10:09:16.351183 | controller | BUILD_TIMEOUT=5400000
2026-03-13 10:09:16.351188 | controller | SELINUX_USE_CURRENT_RANGE=
2026-03-13 10:09:16.351193 | controller | SHLVL=1
2026-03-13 10:09:16.351198 | controller | ZUUL_PATCHSET=49aced80d27e9606127d64e941573b745d7c8bde
2026-03-13 10:09:16.351204 | controller | XDG_SESSION_ID=1
2026-03-13 10:09:16.351209 | controller | ZUUL_BRANCH=main
2026-03-13 10:09:16.351215 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-03-13 10:09:16.351220 | controller | SSH_CLIENT=192.168.26.12 34728 22
2026-03-13 10:09:16.351226 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-03-13 10:09:16.351231 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-03-13 10:09:16.351238 | controller | which_declare=declare -f
2026-03-13 10:09:16.351243 | 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-13 10:09:16.351249 | controller | SELINUX_LEVEL_REQUESTED=
2026-03-13 10:09:16.351254 | controller | ZUUL_CHANGE=3739
2026-03-13 10:09:16.351259 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-03-13 10:09:16.351265 | controller | ZUUL_UUID=df938b3a65c64cca900875da078e3a19
2026-03-13 10:09:16.351270 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-03-13 10:09:16.351275 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-03-13 10:09:16.351281 | controller | }
2026-03-13 10:09:16.615977 | controller | ok: Runtime: 0:00:00.006107
2026-03-13 10:09:16.620737 | 
2026-03-13 10:09:16.620792 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-03-13 10:09:16.633836 | controller | skipping: Conditional result was False
2026-03-13 10:09:16.638455 | 
2026-03-13 10:09:16.638513 | TASK [Symlink /home/zuul-worker/workspace]
2026-03-13 10:09:17.180450 | controller | skipping: Conditional result was False
2026-03-13 10:09:17.185994 | 
2026-03-13 10:09:17.186057 | TASK [Ensure legacy workspace directory]
2026-03-13 10:09:17.446926 | controller | changed
2026-03-13 10:09:17.463664 | 
2026-03-13 10:09:17.463708 | PLAY RECAP
2026-03-13 10:09:17.463751 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-03-13 10:09:17.463773 | 
2026-03-13 10:09:17.528026 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-03-13 10:09:17.528705 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-13 10:09:17.980488 | 
2026-03-13 10:09:17.980576 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-03-13 10:09:17.998918 | 
2026-03-13 10:09:17.998986 | TASK [Create zuul-output directory]
2026-03-13 10:09:18.362273 | controller | changed
2026-03-13 10:09:18.367067 | 
2026-03-13 10:09:18.367142 | TASK [Slurp Zuul inventory test]
2026-03-13 10:09:18.614021 | controller -> localhost | ok
2026-03-13 10:09:18.619275 | 
2026-03-13 10:09:18.619364 | TASK [Save zuul inventory]
2026-03-13 10:09:19.765134 | controller | changed
2026-03-13 10:09:19.769543 | 
2026-03-13 10:09:19.769602 | TASK [Save zuul vars without the change_message]
2026-03-13 10:09:20.783258 | controller | changed
2026-03-13 10:09:20.799551 | 
2026-03-13 10:09:20.799598 | PLAY RECAP
2026-03-13 10:09:20.799640 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-03-13 10:09:20.799660 | 
2026-03-13 10:09:20.861203 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-03-13 10:09:20.861888 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-13 10:09:21.357630 | 
2026-03-13 10:09:21.357724 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-03-13 10:09:21.376408 | 
2026-03-13 10:09:21.376477 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-03-13 10:09:21.394319 | controller | ok
2026-03-13 10:09:21.409739 | 
2026-03-13 10:09:21.409815 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-03-13 10:09:21.433413 | controller | skipping: Conditional result was False
2026-03-13 10:09:21.438785 | 
2026-03-13 10:09:21.438857 | TASK [mirror-info-fork : Create /etc/ci]
2026-03-13 10:09:21.810618 | controller | ok
2026-03-13 10:09:21.815606 | 
2026-03-13 10:09:21.815672 | TASK [mirror-info-fork : Install ci_mirror script]
2026-03-13 10:09:22.715457 | controller | ok
2026-03-13 10:09:22.724726 | 
2026-03-13 10:09:22.724788 | TASK [Prepare workspace]
2026-03-13 10:09:22.741893 | controller | ok
2026-03-13 10:09:22.757186 | 
2026-03-13 10:09:22.757259 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-03-13 10:09:23.099671 | controller | ok
2026-03-13 10:09:23.104814 | 
2026-03-13 10:09:23.104873 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-03-13 10:09:25.450171 | controller | Output suppressed because no_log was given
2026-03-13 10:09:25.458282 | 
2026-03-13 10:09:25.458380 | LOOP [Create zuul-output directory]
2026-03-13 10:09:25.710242 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-03-13 10:09:25.927168 | controller | ok: "/home/zuul/zuul-output/logs"
2026-03-13 10:09:25.932803 | 
2026-03-13 10:09:25.932862 | TASK [Install required packages]
2026-03-13 10:09:46.099173 | controller | ok: Nothing to do
2026-03-13 10:09:46.103941 | 
2026-03-13 10:09:46.104003 | TASK [Install venv]
2026-03-13 10:10:42.799952 | controller | changed
2026-03-13 10:10:42.822571 | 
2026-03-13 10:10:42.822628 | PLAY RECAP
2026-03-13 10:10:42.822672 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-03-13 10:10:42.822692 | 
2026-03-13 10:10:42.888930 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-03-13 10:10:42.889661 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-13 10:10:43.367755 | 
2026-03-13 10:10:43.367843 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-03-13 10:10:43.386797 | 
2026-03-13 10:10:43.386872 | TASK [Gather required facts]
2026-03-13 10:10:43.882894 | controller | ok
2026-03-13 10:10:43.887630 | 
2026-03-13 10:10:43.887697 | TASK [Load environment var if instructed to]
2026-03-13 10:10:43.911255 | controller | skipping: Conditional result was False
2026-03-13 10:10:43.916066 | 
2026-03-13 10:10:43.916126 | TASK [Ensure group_vars dir exists]
2026-03-13 10:10:44.268385 | controller | ok
2026-03-13 10:10:44.274198 | 
2026-03-13 10:10:44.274282 | TASK [Print related variables]
2026-03-13 10:10:44.303071 | controller | ok:
2026-03-13 10:10:44.303197 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-03-13 10:10:44.303226 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer
2026-03-13 10:10:44.307598 | 
2026-03-13 10:10:44.307666 | TASK [Run molecule]
2026-03-13 10:10:45.342948 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-03-13 10:10:45.690330 | controller | INFO     Running bm_redfish > prepare
2026-03-13 10:10:46.313846 | controller |
2026-03-13 10:10:46.313994 | controller | PLAY [Prepare mock iDRAC server] ***********************************************
2026-03-13 10:10:46.314108 | controller |
2026-03-13 10:10:46.314261 | controller | TASK [Create mock server directory] ********************************************
2026-03-13 10:10:46.314378 | controller | Friday 13 March 2026  10:10:46 +0000 (0:00:00.026)       0:00:00.026 **********
2026-03-13 10:10:46.634894 | controller | changed: [instance]
2026-03-13 10:10:47.029067 | controller |
2026-03-13 10:10:47.029108 | controller | TASK [Generate self-signed TLS certificate] ************************************
2026-03-13 10:10:47.029130 | controller | Friday 13 March 2026  10:10:46 +0000 (0:00:00.321)       0:00:00.347 **********
2026-03-13 10:10:47.029146 | controller | changed: [instance]
2026-03-13 10:10:47.521095 | controller |
2026-03-13 10:10:47.521147 | controller | TASK [Copy mock iDRAC server script] *******************************************
2026-03-13 10:10:47.521161 | controller | Friday 13 March 2026  10:10:47 +0000 (0:00:00.393)       0:00:00.741 **********
2026-03-13 10:10:47.521175 | controller | changed: [instance]
2026-03-13 10:10:47.696273 | controller |
2026-03-13 10:10:47.696299 | controller | TASK [Start mock iDRAC server] *************************************************
2026-03-13 10:10:47.696307 | controller | Friday 13 March 2026  10:10:47 +0000 (0:00:00.492)       0:00:01.233 **********
2026-03-13 10:10:47.696318 | controller | changed: [instance]
2026-03-13 10:10:47.881188 | controller |
2026-03-13 10:10:47.881223 | controller | TASK [Record mock server PID] **************************************************
2026-03-13 10:10:47.881231 | controller | Friday 13 March 2026  10:10:47 +0000 (0:00:00.174)       0:00:01.408 **********
2026-03-13 10:10:47.881243 | controller | ok: [instance]
2026-03-13 10:10:47.881361 | controller |
2026-03-13 10:10:47.881371 | controller | TASK [Wait for mock iDRAC to respond] ******************************************
2026-03-13 10:10:47.881458 | controller | Friday 13 March 2026  10:10:47 +0000 (0:00:00.185)       0:00:01.594 **********
2026-03-13 10:10:48.278032 | controller | ok: [instance]
2026-03-13 10:10:48.278150 | controller |
2026-03-13 10:10:48.278166 | controller | PLAY RECAP *********************************************************************
2026-03-13 10:10:48.278280 | controller | instance                   : ok=6    changed=4    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2026-03-13 10:10:48.278366 | controller |
2026-03-13 10:10:48.278453 | controller | Friday 13 March 2026  10:10:48 +0000 (0:00:00.397)       0:00:01.991 **********
2026-03-13 10:10:48.278547 | controller | ===============================================================================
2026-03-13 10:10:48.278628 | controller | Copy mock iDRAC server script ------------------------------------------- 0.49s
2026-03-13 10:10:48.278710 | controller | Wait for mock iDRAC to respond ------------------------------------------ 0.40s
2026-03-13 10:10:48.278798 | controller | Generate self-signed TLS certificate ------------------------------------ 0.39s
2026-03-13 10:10:48.278902 | controller | Create mock server directory -------------------------------------------- 0.32s
2026-03-13 10:10:48.278981 | controller | Record mock server PID -------------------------------------------------- 0.19s
2026-03-13 10:10:48.279069 | controller | Start mock iDRAC server ------------------------------------------------- 0.17s
2026-03-13 10:10:48.329925 | controller | INFO     Running bm_redfish > converge
2026-03-13 10:10:48.725269 | controller |
2026-03-13 10:10:48.725347 | controller | PLAY [Converge -- test bm_* Redfish tasks against mock iDRAC] ******************
2026-03-13 10:10:48.725472 | controller |
2026-03-13 10:10:48.725558 | controller | TASK [Test bm_power_off] *******************************************************
2026-03-13 10:10:48.725663 | controller | Friday 13 March 2026  10:10:48 +0000 (0:00:00.044)       0:00:00.044 **********
2026-03-13 10:10:48.744857 | 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-13 10:10:48.744935 | controller |
2026-03-13 10:10:48.745050 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-13 10:10:48.745162 | controller | Friday 13 March 2026  10:10:48 +0000 (0:00:00.020)       0:00:00.064 **********
2026-03-13 10:10:49.134923 | controller | ok: [instance]
2026-03-13 10:10:49.134969 | controller |
2026-03-13 10:10:49.135081 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-13 10:10:49.135184 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.390)       0:00:00.454 **********
2026-03-13 10:10:49.161579 | controller |
2026-03-13 10:10:49.161724 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:49.161881 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.026)       0:00:00.481 **********
2026-03-13 10:10:49.432721 | controller | ok: [instance]
2026-03-13 10:10:49.432824 | controller |
2026-03-13 10:10:49.432924 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-13 10:10:49.433018 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.271)       0:00:00.752 **********
2026-03-13 10:10:49.447717 | controller | skipping: [instance]
2026-03-13 10:10:49.447809 | controller |
2026-03-13 10:10:49.447911 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-13 10:10:49.448014 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.015)       0:00:00.767 **********
2026-03-13 10:10:49.465450 | controller | skipping: [instance]
2026-03-13 10:10:49.465525 | controller |
2026-03-13 10:10:49.465670 | controller | TASK [Query mock state after power_off (already off)] **************************
2026-03-13 10:10:49.465740 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.017)       0:00:00.785 **********
2026-03-13 10:10:49.735693 | controller | ok: [instance]
2026-03-13 10:10:49.735762 | controller |
2026-03-13 10:10:49.735879 | controller | TASK [Assert host is still Off] ************************************************
2026-03-13 10:10:49.736007 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.269)       0:00:01.055 **********
2026-03-13 10:10:49.754998 | controller | ok: [instance] => {
2026-03-13 10:10:49.755095 | controller |     "changed": false,
2026-03-13 10:10:49.755229 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:49.755333 | controller | }
2026-03-13 10:10:49.755409 | controller |
2026-03-13 10:10:49.755492 | controller | TASK [Reset mock to power On] **************************************************
2026-03-13 10:10:49.755582 | controller | Friday 13 March 2026  10:10:49 +0000 (0:00:00.019)       0:00:01.074 **********
2026-03-13 10:10:50.026109 | controller | ok: [instance]
2026-03-13 10:10:50.026206 | controller |
2026-03-13 10:10:50.026217 | controller | TASK [Include bm_power_off] ****************************************************
2026-03-13 10:10:50.026228 | controller | Friday 13 March 2026  10:10:50 +0000 (0:00:00.270)       0:00:01.345 **********
2026-03-13 10:10:50.050205 | controller |
2026-03-13 10:10:50.318316 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:50.318349 | controller | Friday 13 March 2026  10:10:50 +0000 (0:00:00.024)       0:00:01.369 **********
2026-03-13 10:10:50.318367 | controller | ok: [instance]
2026-03-13 10:10:50.318481 | controller |
2026-03-13 10:10:50.318492 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-13 10:10:50.318568 | controller | Friday 13 March 2026  10:10:50 +0000 (0:00:00.268)       0:00:01.637 **********
2026-03-13 10:10:50.596096 | controller | ok: [instance]
2026-03-13 10:10:50.596197 | controller |
2026-03-13 10:10:50.596313 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-13 10:10:50.596415 | controller | Friday 13 March 2026  10:10:50 +0000 (0:00:00.277)       0:00:01.915 **********
2026-03-13 10:10:50.877348 | controller | ok: [instance]
2026-03-13 10:10:50.877399 | controller |
2026-03-13 10:10:50.877613 | controller | TASK [Query mock state after power_off (was on)] *******************************
2026-03-13 10:10:51.148205 | controller | Friday 13 March 2026  10:10:50 +0000 (0:00:00.281)       0:00:02.196 **********
2026-03-13 10:10:51.148243 | controller | ok: [instance]
2026-03-13 10:10:51.148271 | controller |
2026-03-13 10:10:51.148466 | controller | TASK [Assert host is now Off] **************************************************
2026-03-13 10:10:51.165818 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.270)       0:00:02.467 **********
2026-03-13 10:10:51.165838 | controller | ok: [instance] => {
2026-03-13 10:10:51.187234 | controller |     "changed": false,
2026-03-13 10:10:51.187263 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:51.187279 | controller | }
2026-03-13 10:10:51.187286 | controller |
2026-03-13 10:10:51.187292 | controller | TASK [Test bm_power_on] ********************************************************
2026-03-13 10:10:51.187298 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.017)       0:00:02.485 **********
2026-03-13 10:10:51.187309 | 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-13 10:10:51.455671 | controller |
2026-03-13 10:10:51.455695 | controller | TASK [Reset mock to power On] **************************************************
2026-03-13 10:10:51.455703 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.021)       0:00:02.506 **********
2026-03-13 10:10:51.455712 | controller | ok: [instance]
2026-03-13 10:10:51.479894 | controller |
2026-03-13 10:10:51.479912 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-13 10:10:51.479919 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.268)       0:00:02.774 **********
2026-03-13 10:10:51.479928 | controller |
2026-03-13 10:10:51.749246 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:51.749278 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.024)       0:00:02.799 **********
2026-03-13 10:10:51.749291 | controller | ok: [instance]
2026-03-13 10:10:51.749316 | controller |
2026-03-13 10:10:51.749522 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-13 10:10:51.764257 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.269)       0:00:03.068 **********
2026-03-13 10:10:51.764297 | controller | skipping: [instance]
2026-03-13 10:10:51.764330 | controller |
2026-03-13 10:10:51.764357 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-13 10:10:51.764487 | controller | Friday 13 March 2026  10:10:51 +0000 (0:00:00.015)       0:00:03.083 **********
2026-03-13 10:10:52.047581 | controller | ok: [instance]
2026-03-13 10:10:52.316258 | controller |
2026-03-13 10:10:52.316297 | controller | TASK [Query mock state after power_on (already on)] ****************************
2026-03-13 10:10:52.316307 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.283)       0:00:03.366 **********
2026-03-13 10:10:52.316321 | controller | ok: [instance]
2026-03-13 10:10:52.316355 | controller |
2026-03-13 10:10:52.316536 | controller | TASK [Assert host is still On] *************************************************
2026-03-13 10:10:52.334374 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.268)       0:00:03.635 **********
2026-03-13 10:10:52.334414 | controller | ok: [instance] => {
2026-03-13 10:10:52.334447 | controller |     "changed": false,
2026-03-13 10:10:52.334456 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:52.334466 | controller | }
2026-03-13 10:10:52.334797 | controller |
2026-03-13 10:10:52.608029 | controller | TASK [Reset mock to power Off] *************************************************
2026-03-13 10:10:52.608057 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.017)       0:00:03.653 **********
2026-03-13 10:10:52.608069 | controller | ok: [instance]
2026-03-13 10:10:52.631913 | controller |
2026-03-13 10:10:52.631930 | controller | TASK [Include bm_power_on] *****************************************************
2026-03-13 10:10:52.631937 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.273)       0:00:03.927 **********
2026-03-13 10:10:52.631946 | controller |
2026-03-13 10:10:52.910587 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:52.910607 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.024)       0:00:03.951 **********
2026-03-13 10:10:52.910617 | controller | ok: [instance]
2026-03-13 10:10:53.186823 | controller |
2026-03-13 10:10:53.186842 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-13 10:10:53.186849 | controller | Friday 13 March 2026  10:10:52 +0000 (0:00:00.278)       0:00:04.229 **********
2026-03-13 10:10:53.186859 | controller | ok: [instance]
2026-03-13 10:10:53.467001 | controller |
2026-03-13 10:10:53.467021 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-13 10:10:53.467028 | controller | Friday 13 March 2026  10:10:53 +0000 (0:00:00.276)       0:00:04.506 **********
2026-03-13 10:10:53.467038 | controller | ok: [instance]
2026-03-13 10:10:53.736098 | controller |
2026-03-13 10:10:53.736139 | controller | TASK [Query mock state after power_on (was off)] *******************************
2026-03-13 10:10:53.736150 | controller | Friday 13 March 2026  10:10:53 +0000 (0:00:00.280)       0:00:04.786 **********
2026-03-13 10:10:53.736160 | controller | ok: [instance]
2026-03-13 10:10:53.757273 | controller |
2026-03-13 10:10:53.757311 | controller | TASK [Assert host is now On] ***************************************************
2026-03-13 10:10:53.757321 | controller | Friday 13 March 2026  10:10:53 +0000 (0:00:00.269)       0:00:05.055 **********
2026-03-13 10:10:53.757334 | controller | ok: [instance] => {
2026-03-13 10:10:53.757366 | controller |     "changed": false,
2026-03-13 10:10:53.757374 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:53.757381 | controller | }
2026-03-13 10:10:53.757388 | controller |
2026-03-13 10:10:53.757397 | controller | TASK [Test bm_check_usb_boot] **************************************************
2026-03-13 10:10:53.780090 | controller | Friday 13 March 2026  10:10:53 +0000 (0:00:00.020)       0:00:05.076 **********
2026-03-13 10:10:53.780114 | 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-13 10:10:54.047634 | controller |
2026-03-13 10:10:54.047655 | controller | TASK [Reset mock with usb_boot Enabled] ****************************************
2026-03-13 10:10:54.047662 | controller | Friday 13 March 2026  10:10:53 +0000 (0:00:00.023)       0:00:05.099 **********
2026-03-13 10:10:54.047672 | controller | ok: [instance]
2026-03-13 10:10:54.071865 | controller |
2026-03-13 10:10:54.071882 | controller | TASK [Include bm_check_usb_boot] ***********************************************
2026-03-13 10:10:54.071889 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.267)       0:00:05.367 **********
2026-03-13 10:10:54.071898 | controller |
2026-03-13 10:10:54.356011 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-13 10:10:54.356039 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.024)       0:00:05.391 **********
2026-03-13 10:10:54.356051 | controller | ok: [instance]
2026-03-13 10:10:54.387875 | controller |
2026-03-13 10:10:54.387899 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-13 10:10:54.387908 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.283)       0:00:05.675 **********
2026-03-13 10:10:54.387920 | controller | ok: [instance]
2026-03-13 10:10:54.415417 | controller |
2026-03-13 10:10:54.415450 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-13 10:10:54.415460 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.031)       0:00:05.707 **********
2026-03-13 10:10:54.415471 | controller | skipping: [instance]
2026-03-13 10:10:54.441378 | controller |
2026-03-13 10:10:54.441465 | controller | TASK [Assert _usb_boot_enabled is true] ****************************************
2026-03-13 10:10:54.441480 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.027)       0:00:05.734 **********
2026-03-13 10:10:54.441503 | controller | ok: [instance] => {
2026-03-13 10:10:54.441557 | controller |     "changed": false,
2026-03-13 10:10:54.441568 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:54.441582 | controller | }
2026-03-13 10:10:54.441595 | controller |
2026-03-13 10:10:54.724600 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-13 10:10:54.724632 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.025)       0:00:05.760 **********
2026-03-13 10:10:54.724643 | controller | ok: [instance]
2026-03-13 10:10:54.749502 | controller |
2026-03-13 10:10:54.749525 | controller | TASK [Include bm_check_usb_boot (expect failure)] ******************************
2026-03-13 10:10:54.749534 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.283)       0:00:06.043 **********
2026-03-13 10:10:54.749546 | controller |
2026-03-13 10:10:55.042333 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-13 10:10:55.042401 | controller | Friday 13 March 2026  10:10:54 +0000 (0:00:00.024)       0:00:06.068 **********
2026-03-13 10:10:55.042436 | controller | ok: [instance]
2026-03-13 10:10:55.072334 | controller |
2026-03-13 10:10:55.072387 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-13 10:10:55.072397 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.292)       0:00:06.361 **********
2026-03-13 10:10:55.072420 | controller | ok: [instance]
2026-03-13 10:10:55.072458 | controller |
2026-03-13 10:10:55.072469 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-13 10:10:55.072587 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.029)       0:00:06.391 **********
2026-03-13 10:10:55.096818 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-13 10:10:55.101617 | controller |
2026-03-13 10:10:55.121242 | controller | TASK [Assert failure was about GenericUsbBoot] *********************************
2026-03-13 10:10:55.121282 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.029)       0:00:06.420 **********
2026-03-13 10:10:55.121298 | controller | ok: [instance] => {
2026-03-13 10:10:55.121901 | controller |     "changed": false,
2026-03-13 10:10:55.154443 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:55.154476 | controller | }
2026-03-13 10:10:55.154489 | controller |
2026-03-13 10:10:55.154500 | controller | TASK [Test bm_ensure_usb_boot] *************************************************
2026-03-13 10:10:55.154510 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.019)       0:00:06.440 **********
2026-03-13 10:10:55.154526 | 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-13 10:10:55.154808 | controller |
2026-03-13 10:10:55.154994 | controller | TASK [Reset mock with usb_boot Enabled and host Off] ***************************
2026-03-13 10:10:55.155149 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.033)       0:00:06.473 **********
2026-03-13 10:10:55.448179 | controller | ok: [instance]
2026-03-13 10:10:55.479769 | controller |
2026-03-13 10:10:55.479796 | controller | TASK [Include bm_ensure_usb_boot] **********************************************
2026-03-13 10:10:55.479809 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.293)       0:00:06.767 **********
2026-03-13 10:10:55.479824 | controller |
2026-03-13 10:10:55.502284 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-13 10:10:55.502316 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.031)       0:00:06.799 **********
2026-03-13 10:10:55.502329 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-13 10:10:55.502515 | controller |
2026-03-13 10:10:55.502535 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-13 10:10:55.789250 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.022)       0:00:06.821 **********
2026-03-13 10:10:55.789307 | controller | ok: [instance]
2026-03-13 10:10:55.789365 | controller |
2026-03-13 10:10:55.789396 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-13 10:10:55.789407 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.287)       0:00:07.108 **********
2026-03-13 10:10:55.822207 | controller | ok: [instance]
2026-03-13 10:10:55.855218 | controller |
2026-03-13 10:10:55.855253 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-13 10:10:55.855262 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.032)       0:00:07.141 **********
2026-03-13 10:10:55.855274 | controller | skipping: [instance]
2026-03-13 10:10:55.855528 | controller |
2026-03-13 10:10:55.855546 | controller | TASK [Query mock state] ********************************************************
2026-03-13 10:10:55.855556 | controller | Friday 13 March 2026  10:10:55 +0000 (0:00:00.032)       0:00:07.173 **********
2026-03-13 10:10:56.141747 | controller | ok: [instance]
2026-03-13 10:10:56.163968 | controller |
2026-03-13 10:10:56.163985 | controller | TASK [Assert host stayed Off (no power cycle needed)] **************************
2026-03-13 10:10:56.163994 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.286)       0:00:07.460 **********
2026-03-13 10:10:56.164003 | controller | ok: [instance] => {
2026-03-13 10:10:56.452154 | controller |     "changed": false,
2026-03-13 10:10:56.452204 | controller |     "msg": "All assertions passed"
2026-03-13 10:10:56.452213 | controller | }
2026-03-13 10:10:56.452220 | controller |
2026-03-13 10:10:56.452226 | controller | TASK [Reset mock with usb_boot Disabled and host Off] **************************
2026-03-13 10:10:56.452232 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.021)       0:00:07.482 **********
2026-03-13 10:10:56.452251 | controller | ok: [instance]
2026-03-13 10:10:56.483955 | controller |
2026-03-13 10:10:56.483985 | controller | TASK [Include bm_ensure_usb_boot with auto-enable] *****************************
2026-03-13 10:10:56.483998 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.288)       0:00:07.770 **********
2026-03-13 10:10:56.484013 | controller |
2026-03-13 10:10:56.506108 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-13 10:10:56.506166 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.032)       0:00:07.803 **********
2026-03-13 10:10:56.506203 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-13 10:10:56.790890 | controller |
2026-03-13 10:10:56.790910 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-13 10:10:56.790924 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.022)       0:00:07.825 **********
2026-03-13 10:10:56.790933 | controller | ok: [instance]
2026-03-13 10:10:56.824278 | controller |
2026-03-13 10:10:56.824322 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-13 10:10:56.824332 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.285)       0:00:08.110 **********
2026-03-13 10:10:56.824345 | controller | ok: [instance]
2026-03-13 10:10:56.824379 | controller |
2026-03-13 10:10:56.824705 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-13 10:10:56.851524 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.033)       0:00:08.143 **********
2026-03-13 10:10:56.851562 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-13 10:10:56.857079 | controller |
2026-03-13 10:10:56.886211 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-13 10:10:56.886243 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.032)       0:00:08.176 **********
2026-03-13 10:10:56.886254 | controller | skipping: [instance]
2026-03-13 10:10:56.886470 | controller |
2026-03-13 10:10:56.886495 | controller | TASK [reproducer : Set GenericUsbBoot BIOS attribute] **************************
2026-03-13 10:10:57.167672 | controller | Friday 13 March 2026  10:10:56 +0000 (0:00:00.029)       0:00:08.205 **********
2026-03-13 10:10:57.167694 | controller | ok: [instance]
2026-03-13 10:10:57.446211 | controller |
2026-03-13 10:10:57.446229 | controller | TASK [reproducer : Create BIOS config job to schedule the change] **************
2026-03-13 10:10:57.446236 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.281)       0:00:08.487 **********
2026-03-13 10:10:57.446244 | controller | ok: [instance]
2026-03-13 10:10:57.469567 | controller |
2026-03-13 10:10:57.469589 | controller | TASK [reproducer : Power off before applying BIOS change] **********************
2026-03-13 10:10:57.469598 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.278)       0:00:08.765 **********
2026-03-13 10:10:57.469609 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-13 10:10:57.747379 | controller |
2026-03-13 10:10:57.747397 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:57.747405 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.023)       0:00:08.788 **********
2026-03-13 10:10:57.747414 | controller | ok: [instance]
2026-03-13 10:10:57.765652 | controller |
2026-03-13 10:10:57.765668 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-13 10:10:57.765675 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.277)       0:00:09.066 **********
2026-03-13 10:10:57.765683 | controller | skipping: [instance]
2026-03-13 10:10:57.783862 | controller |
2026-03-13 10:10:57.783879 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-13 10:10:57.783887 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.018)       0:00:09.084 **********
2026-03-13 10:10:57.783896 | controller | skipping: [instance]
2026-03-13 10:10:57.809753 | controller |
2026-03-13 10:10:57.809771 | controller | TASK [reproducer : Power on to apply BIOS config job during POST] **************
2026-03-13 10:10:57.809786 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.017)       0:00:09.102 **********
2026-03-13 10:10:57.809795 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_on.yml for instance
2026-03-13 10:10:58.094999 | controller |
2026-03-13 10:10:58.095018 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:58.095025 | controller | Friday 13 March 2026  10:10:57 +0000 (0:00:00.025)       0:00:09.128 **********
2026-03-13 10:10:58.095034 | controller | ok: [instance]
2026-03-13 10:10:58.372892 | controller |
2026-03-13 10:10:58.372910 | controller | TASK [reproducer : Power on bare metal host] ***********************************
2026-03-13 10:10:58.372918 | controller | Friday 13 March 2026  10:10:58 +0000 (0:00:00.285)       0:00:09.414 **********
2026-03-13 10:10:58.372927 | controller | ok: [instance]
2026-03-13 10:10:58.650242 | controller |
2026-03-13 10:10:58.650268 | controller | TASK [reproducer : Wait for host POST to complete] *****************************
2026-03-13 10:10:58.650278 | controller | Friday 13 March 2026  10:10:58 +0000 (0:00:00.277)       0:00:09.692 **********
2026-03-13 10:10:58.650289 | controller | ok: [instance]
2026-03-13 10:10:58.650447 | controller |
2026-03-13 10:10:58.650466 | controller | TASK [reproducer : Power off after BIOS change applied] ************************
2026-03-13 10:10:58.677618 | controller | Friday 13 March 2026  10:10:58 +0000 (0:00:00.277)       0:00:09.969 **********
2026-03-13 10:10:58.677641 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_power_off.yml for instance
2026-03-13 10:10:58.954250 | controller |
2026-03-13 10:10:58.954306 | controller | TASK [reproducer : Query current power state] **********************************
2026-03-13 10:10:58.954316 | controller | Friday 13 March 2026  10:10:58 +0000 (0:00:00.027)       0:00:09.996 **********
2026-03-13 10:10:58.954340 | controller | ok: [instance]
2026-03-13 10:10:59.230237 | controller |
2026-03-13 10:10:59.230276 | controller | TASK [reproducer : Force power off via Redfish] ********************************
2026-03-13 10:10:59.230284 | controller | Friday 13 March 2026  10:10:58 +0000 (0:00:00.276)       0:00:10.273 **********
2026-03-13 10:10:59.230296 | controller | ok: [instance]
2026-03-13 10:10:59.507023 | controller |
2026-03-13 10:10:59.507048 | controller | TASK [reproducer : Wait for host to power off] *********************************
2026-03-13 10:10:59.507056 | controller | Friday 13 March 2026  10:10:59 +0000 (0:00:00.276)       0:00:10.549 **********
2026-03-13 10:10:59.507065 | controller | ok: [instance]
2026-03-13 10:10:59.783855 | controller |
2026-03-13 10:10:59.783876 | controller | TASK [Query mock state after auto-enable] **************************************
2026-03-13 10:10:59.783884 | controller | Friday 13 March 2026  10:10:59 +0000 (0:00:00.276)       0:00:10.825 **********
2026-03-13 10:10:59.783893 | controller | ok: [instance]
2026-03-13 10:10:59.807071 | controller |
2026-03-13 10:10:59.807090 | controller | TASK [Assert BIOS updated and host left Off] ***********************************
2026-03-13 10:10:59.807098 | controller | Friday 13 March 2026  10:10:59 +0000 (0:00:00.277)       0:00:11.103 **********
2026-03-13 10:10:59.807107 | controller | ok: [instance] => {
2026-03-13 10:11:00.082265 | controller |     "changed": false,
2026-03-13 10:11:00.082311 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:00.082319 | controller | }
2026-03-13 10:11:00.082326 | controller |
2026-03-13 10:11:00.082332 | controller | TASK [Reset mock with usb_boot Disabled] ***************************************
2026-03-13 10:11:00.082338 | controller | Friday 13 March 2026  10:10:59 +0000 (0:00:00.022)       0:00:11.126 **********
2026-03-13 10:11:00.082350 | controller | ok: [instance]
2026-03-13 10:11:00.082380 | controller |
2026-03-13 10:11:00.082508 | controller | TASK [Include bm_ensure_usb_boot without auto-enable (expect failure)] *********
2026-03-13 10:11:00.082530 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.275)       0:00:11.401 **********
2026-03-13 10:11:00.112505 | controller |
2026-03-13 10:11:00.135926 | controller | TASK [reproducer : Check current GenericUsbBoot state] *************************
2026-03-13 10:11:00.135948 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.030)       0:00:11.432 **********
2026-03-13 10:11:00.135961 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/reproducer/tasks/bm_check_usb_boot.yml for instance
2026-03-13 10:11:00.419354 | controller |
2026-03-13 10:11:00.419374 | controller | TASK [reproducer : Read GenericUsbBoot BIOS attribute] *************************
2026-03-13 10:11:00.419381 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.023)       0:00:11.455 **********
2026-03-13 10:11:00.419390 | controller | ok: [instance]
2026-03-13 10:11:00.449757 | controller |
2026-03-13 10:11:00.449775 | controller | TASK [reproducer : Set GenericUsbBoot status fact] *****************************
2026-03-13 10:11:00.449782 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.283)       0:00:11.738 **********
2026-03-13 10:11:00.449791 | controller | ok: [instance]
2026-03-13 10:11:00.507520 | controller |
2026-03-13 10:11:00.507553 | controller | TASK [reproducer : Fail if GenericUsbBoot is disabled] *************************
2026-03-13 10:11:00.507566 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.030)       0:00:11.769 **********
2026-03-13 10:11:00.507583 | controller | fatal: [instance]: FAILED! => {"changed": false, "msg": "GenericUsbBoot is Disabled in BIOS. VirtualMedia cannot boot host localhost:8443."}
2026-03-13 10:11:00.512700 | controller |
2026-03-13 10:11:00.538774 | controller | TASK [reproducer : Fail if auto-enable is off] *********************************
2026-03-13 10:11:00.538806 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.062)       0:00:11.831 **********
2026-03-13 10:11:00.538825 | 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-13 10:11:00.543228 | controller |
2026-03-13 10:11:00.543726 | controller | TASK [Assert failure mentions GenericUsbBoot or auto-enable] *******************
2026-03-13 10:11:00.563232 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.030)       0:00:11.862 **********
2026-03-13 10:11:00.563291 | controller | ok: [instance] => {
2026-03-13 10:11:00.563338 | controller |     "changed": false,
2026-03-13 10:11:00.563348 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:00.563356 | controller | }
2026-03-13 10:11:00.563363 | controller |
2026-03-13 10:11:00.563373 | controller | TASK [Test bm_eject_vmedia] ****************************************************
2026-03-13 10:11:00.563457 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.019)       0:00:11.882 **********
2026-03-13 10:11:00.592549 | 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-13 10:11:00.592769 | controller |
2026-03-13 10:11:00.592986 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-13 10:11:00.593132 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.029)       0:00:11.912 **********
2026-03-13 10:11:00.862128 | controller | ok: [instance]
2026-03-13 10:11:00.862298 | controller |
2026-03-13 10:11:00.862448 | controller | TASK [Include bm_eject_vmedia] *************************************************
2026-03-13 10:11:00.862574 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.269)       0:00:12.181 **********
2026-03-13 10:11:00.886191 | controller |
2026-03-13 10:11:00.886359 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-13 10:11:00.886513 | controller | Friday 13 March 2026  10:11:00 +0000 (0:00:00.024)       0:00:12.205 **********
2026-03-13 10:11:01.160921 | controller | ok: [instance]
2026-03-13 10:11:01.161027 | controller |
2026-03-13 10:11:01.161215 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-13 10:11:01.161318 | controller | Friday 13 March 2026  10:11:01 +0000 (0:00:00.274)       0:00:12.480 **********
2026-03-13 10:11:06.187718 | controller | Pausing for 5 seconds
2026-03-13 10:11:06.187925 | controller | ok: [instance]
2026-03-13 10:11:06.188132 | controller |
2026-03-13 10:11:06.188337 | controller | TASK [Query mock state after eject] ********************************************
2026-03-13 10:11:06.188420 | controller | Friday 13 March 2026  10:11:06 +0000 (0:00:05.026)       0:00:17.506 **********
2026-03-13 10:11:06.465774 | controller | ok: [instance]
2026-03-13 10:11:06.465985 | controller |
2026-03-13 10:11:06.466015 | controller | TASK [Assert VirtualMedia is ejected] ******************************************
2026-03-13 10:11:06.494229 | controller | Friday 13 March 2026  10:11:06 +0000 (0:00:00.277)       0:00:17.784 **********
2026-03-13 10:11:06.494262 | controller | ok: [instance] => {
2026-03-13 10:11:06.494293 | controller |     "changed": false,
2026-03-13 10:11:06.494302 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:06.494616 | controller | }
2026-03-13 10:11:06.776243 | controller |
2026-03-13 10:11:06.776267 | controller | TASK [Reset mock with VirtualMedia not inserted] *******************************
2026-03-13 10:11:06.776276 | controller | Friday 13 March 2026  10:11:06 +0000 (0:00:00.028)       0:00:17.813 **********
2026-03-13 10:11:06.776287 | controller | ok: [instance]
2026-03-13 10:11:06.776318 | controller |
2026-03-13 10:11:06.776479 | controller | TASK [Include bm_eject_vmedia (idempotent)] ************************************
2026-03-13 10:11:06.800950 | controller | Friday 13 March 2026  10:11:06 +0000 (0:00:00.282)       0:00:18.095 **********
2026-03-13 10:11:06.800968 | controller |
2026-03-13 10:11:07.075833 | controller | TASK [reproducer : Eject VirtualMedia] *****************************************
2026-03-13 10:11:07.075854 | controller | Friday 13 March 2026  10:11:06 +0000 (0:00:00.024)       0:00:18.120 **********
2026-03-13 10:11:07.075865 | controller | ok: [instance]
2026-03-13 10:11:12.103282 | controller |
2026-03-13 10:11:12.103316 | controller | TASK [reproducer : Wait for VirtualMedia eject to settle] **********************
2026-03-13 10:11:12.103325 | controller | Friday 13 March 2026  10:11:07 +0000 (0:00:00.274)       0:00:18.395 **********
2026-03-13 10:11:12.103336 | controller | Pausing for 5 seconds
2026-03-13 10:11:12.372281 | controller | ok: [instance]
2026-03-13 10:11:12.372320 | controller |
2026-03-13 10:11:12.372330 | controller | TASK [Query mock state] ********************************************************
2026-03-13 10:11:12.372338 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:05.026)       0:00:23.421 **********
2026-03-13 10:11:12.372351 | controller | ok: [instance]
2026-03-13 10:11:12.372382 | controller |
2026-03-13 10:11:12.372392 | controller | TASK [Assert VirtualMedia is still not inserted] *******************************
2026-03-13 10:11:12.372419 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:00.269)       0:00:23.691 **********
2026-03-13 10:11:12.402068 | controller | ok: [instance] => {
2026-03-13 10:11:12.436279 | controller |     "changed": false,
2026-03-13 10:11:12.436312 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:12.436326 | controller | }
2026-03-13 10:11:12.436337 | controller |
2026-03-13 10:11:12.436347 | controller | TASK [Test bm_discover_vmedia_target] ******************************************
2026-03-13 10:11:12.436357 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:00.029)       0:00:23.721 **********
2026-03-13 10:11:12.436373 | 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-13 10:11:12.436419 | controller |
2026-03-13 10:11:12.436618 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-13 10:11:12.718562 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:00.034)       0:00:23.755 **********
2026-03-13 10:11:12.718584 | controller | ok: [instance]
2026-03-13 10:11:12.752700 | controller |
2026-03-13 10:11:12.752721 | controller | TASK [Include bm_discover_vmedia_target (auto-discover)] ***********************
2026-03-13 10:11:12.752730 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:00.282)       0:00:24.037 **********
2026-03-13 10:11:12.752741 | controller |
2026-03-13 10:11:13.033857 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-13 10:11:13.033884 | controller | Friday 13 March 2026  10:11:12 +0000 (0:00:00.034)       0:00:24.072 **********
2026-03-13 10:11:13.033895 | controller | ok: [instance]
2026-03-13 10:11:14.382364 | controller |
2026-03-13 10:11:14.382410 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-13 10:11:14.382424 | controller | Friday 13 March 2026  10:11:13 +0000 (0:00:00.280)       0:00:24.352 **********
2026-03-13 10:11:14.382441 | controller | ok: [instance] => (item=Boot0001)
2026-03-13 10:11:14.382485 | controller | ok: [instance] => (item=Boot0003)
2026-03-13 10:11:14.382496 | controller | ok: [instance] => (item=Boot0004)
2026-03-13 10:11:14.382505 | controller | ok: [instance] => (item=Boot0005)
2026-03-13 10:11:14.382515 | controller | ok: [instance] => (item=Boot0006)
2026-03-13 10:11:14.382524 | controller |
2026-03-13 10:11:14.382538 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-13 10:11:14.418909 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:01.347)       0:00:25.700 **********
2026-03-13 10:11:14.418958 | controller | ok: [instance]
2026-03-13 10:11:14.439953 | controller |
2026-03-13 10:11:14.439985 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-13 10:11:14.439999 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.037)       0:00:25.738 **********
2026-03-13 10:11:14.440015 | controller | skipping: [instance]
2026-03-13 10:11:14.503212 | controller |
2026-03-13 10:11:14.503241 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-13 10:11:14.503251 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.020)       0:00:25.758 **********
2026-03-13 10:11:14.503263 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-13 10:11:14.503779 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-13 10:11:14.503800 | controller | ok: [instance] => (item=Virtual Optical Drive)
2026-03-13 10:11:14.524030 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-13 10:11:14.524063 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-13 10:11:14.524076 | controller |
2026-03-13 10:11:14.524087 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-13 10:11:14.524098 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.063)       0:00:25.822 **********
2026-03-13 10:11:14.524113 | controller | skipping: [instance]
2026-03-13 10:11:14.524427 | controller |
2026-03-13 10:11:14.524567 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-13 10:11:14.524696 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.020)       0:00:25.843 **********
2026-03-13 10:11:14.543680 | controller | ok: [instance] => {
2026-03-13 10:11:14.543959 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-13 10:11:14.545308 | controller | }
2026-03-13 10:11:14.545509 | controller |
2026-03-13 10:11:14.545669 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-13 10:11:14.545780 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.019)       0:00:25.863 **********
2026-03-13 10:11:14.828069 | controller | ok: [instance]
2026-03-13 10:11:24.858292 | controller |
2026-03-13 10:11:24.858356 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-13 10:11:24.858367 | controller | Friday 13 March 2026  10:11:14 +0000 (0:00:00.283)       0:00:26.147 **********
2026-03-13 10:11:24.858383 | controller | Pausing for 10 seconds
2026-03-13 10:11:24.858438 | controller | ok: [instance]
2026-03-13 10:11:24.858448 | controller |
2026-03-13 10:11:24.858507 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-13 10:11:24.858546 | controller | Friday 13 March 2026  10:11:24 +0000 (0:00:10.030)       0:00:36.177 **********
2026-03-13 10:11:25.134042 | controller | ok: [instance]
2026-03-13 10:11:25.409809 | controller |
2026-03-13 10:11:25.409842 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-13 10:11:25.409851 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.275)       0:00:36.453 **********
2026-03-13 10:11:25.409864 | controller | ok: [instance]
2026-03-13 10:11:25.433266 | controller |
2026-03-13 10:11:25.433305 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-13 10:11:25.433316 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.275)       0:00:36.728 **********
2026-03-13 10:11:25.433340 | controller | ok: [instance] => {
2026-03-13 10:11:25.433372 | controller |     "changed": false,
2026-03-13 10:11:25.433382 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:25.433762 | controller | }
2026-03-13 10:11:25.713728 | controller |
2026-03-13 10:11:25.713748 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-13 10:11:25.713756 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.023)       0:00:36.752 **********
2026-03-13 10:11:25.713765 | controller | ok: [instance]
2026-03-13 10:11:25.749257 | controller |
2026-03-13 10:11:25.749294 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-13 10:11:25.749314 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.280)       0:00:37.033 **********
2026-03-13 10:11:25.749328 | controller | ok: [instance] => {
2026-03-13 10:11:25.749363 | controller |     "changed": false,
2026-03-13 10:11:25.749393 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:25.749961 | controller | }
2026-03-13 10:11:25.785024 | controller |
2026-03-13 10:11:25.785053 | controller | TASK [Assert discovered path is Virtual Optical Drive] *************************
2026-03-13 10:11:25.785062 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.035)       0:00:37.068 **********
2026-03-13 10:11:25.785071 | controller | ok: [instance] => {
2026-03-13 10:11:25.785093 | controller |     "changed": false,
2026-03-13 10:11:25.785099 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:25.785107 | controller | }
2026-03-13 10:11:25.785442 | controller |
2026-03-13 10:11:26.058756 | controller | TASK [Query mock state after discover] *****************************************
2026-03-13 10:11:26.058778 | controller | Friday 13 March 2026  10:11:25 +0000 (0:00:00.035)       0:00:37.104 **********
2026-03-13 10:11:26.058791 | controller | ok: [instance]
2026-03-13 10:11:26.085047 | controller |
2026-03-13 10:11:26.085070 | controller | TASK [Assert boot override was set] ********************************************
2026-03-13 10:11:26.085080 | controller | Friday 13 March 2026  10:11:26 +0000 (0:00:00.273)       0:00:37.377 **********
2026-03-13 10:11:26.085092 | controller | ok: [instance] => {
2026-03-13 10:11:26.366366 | controller |     "changed": false,
2026-03-13 10:11:26.366386 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:26.366394 | controller | }
2026-03-13 10:11:26.366400 | controller |
2026-03-13 10:11:26.366406 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-13 10:11:26.366411 | controller | Friday 13 March 2026  10:11:26 +0000 (0:00:00.026)       0:00:37.404 **********
2026-03-13 10:11:26.366426 | controller | ok: [instance]
2026-03-13 10:11:26.366564 | controller |
2026-03-13 10:11:26.366706 | controller | TASK [Include bm_discover_vmedia_target with valid explicit path] **************
2026-03-13 10:11:26.366835 | controller | Friday 13 March 2026  10:11:26 +0000 (0:00:00.281)       0:00:37.685 **********
2026-03-13 10:11:26.398801 | controller |
2026-03-13 10:11:26.399004 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-13 10:11:26.399179 | controller | Friday 13 March 2026  10:11:26 +0000 (0:00:00.031)       0:00:37.717 **********
2026-03-13 10:11:26.668018 | controller | ok: [instance]
2026-03-13 10:11:26.668245 | controller |
2026-03-13 10:11:26.668411 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-13 10:11:26.668540 | controller | Friday 13 March 2026  10:11:26 +0000 (0:00:00.269)       0:00:37.987 **********
2026-03-13 10:11:27.976860 | controller | ok: [instance] => (item=Boot0001)
2026-03-13 10:11:28.013234 | controller | ok: [instance] => (item=Boot0003)
2026-03-13 10:11:28.013256 | controller | ok: [instance] => (item=Boot0004)
2026-03-13 10:11:28.013265 | controller | ok: [instance] => (item=Boot0005)
2026-03-13 10:11:28.013272 | controller | ok: [instance] => (item=Boot0006)
2026-03-13 10:11:28.013279 | controller |
2026-03-13 10:11:28.013286 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-13 10:11:28.013293 | controller | Friday 13 March 2026  10:11:27 +0000 (0:00:01.308)       0:00:39.295 **********
2026-03-13 10:11:28.013311 | controller | ok: [instance]
2026-03-13 10:11:28.052361 | controller |
2026-03-13 10:11:28.052405 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-13 10:11:28.052419 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.036)       0:00:39.332 **********
2026-03-13 10:11:28.052437 | controller | ok: [instance] => {
2026-03-13 10:11:28.052485 | controller |     "changed": false,
2026-03-13 10:11:28.052502 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:28.052513 | controller | }
2026-03-13 10:11:28.052523 | controller |
2026-03-13 10:11:28.052536 | controller | TASK [reproducer : Find Virtual Optical Drive boot path] ***********************
2026-03-13 10:11:28.105262 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.039)       0:00:39.371 **********
2026-03-13 10:11:28.105306 | controller | skipping: [instance] => (item=PXE Device 1: Embedded NIC 1 Port 1 Partition 1)
2026-03-13 10:11:28.105336 | controller | skipping: [instance] => (item=Virtual Floppy Drive)
2026-03-13 10:11:28.105347 | controller | skipping: [instance] => (item=Virtual Optical Drive)
2026-03-13 10:11:28.105890 | controller | skipping: [instance] => (item=Integrated RAID Controller 1: Red Hat Enterprise Linux)
2026-03-13 10:11:28.126142 | controller | skipping: [instance] => (item=Generic USB Boot)
2026-03-13 10:11:28.126188 | controller | skipping: [instance]
2026-03-13 10:11:28.126202 | controller |
2026-03-13 10:11:28.126214 | controller | TASK [reproducer : Fail if no Virtual Optical Drive found] *********************
2026-03-13 10:11:28.126223 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.052)       0:00:39.423 **********
2026-03-13 10:11:28.126235 | controller | skipping: [instance]
2026-03-13 10:11:28.144888 | controller |
2026-03-13 10:11:28.144910 | controller | TASK [reproducer : Show VirtualMedia UEFI boot target] *************************
2026-03-13 10:11:28.144920 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.021)       0:00:39.445 **********
2026-03-13 10:11:28.144930 | controller | ok: [instance] => {
2026-03-13 10:11:28.145106 | controller |     "msg": "VirtualMedia UEFI path: PciRoot(0x0)/Pci(0x14,0x0)/USB(0xD,0x0)/USB(0x0,0x0)/USB(0x2,0x0)/Unit(0x0)"
2026-03-13 10:11:28.145305 | controller | }
2026-03-13 10:11:28.145428 | controller |
2026-03-13 10:11:28.145563 | controller | TASK [reproducer : Clear pending iDRAC config jobs that block boot override] ***
2026-03-13 10:11:28.145689 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.019)       0:00:39.464 **********
2026-03-13 10:11:28.428984 | controller | ok: [instance]
2026-03-13 10:11:38.458296 | controller |
2026-03-13 10:11:38.458347 | controller | TASK [reproducer : Wait for iDRAC to settle after clearing jobs] ***************
2026-03-13 10:11:38.458360 | controller | Friday 13 March 2026  10:11:28 +0000 (0:00:00.283)       0:00:39.748 **********
2026-03-13 10:11:38.458377 | controller | Pausing for 10 seconds
2026-03-13 10:11:38.747207 | controller | ok: [instance]
2026-03-13 10:11:38.747240 | controller |
2026-03-13 10:11:38.747248 | controller | TASK [reproducer : Set one-time boot from Virtual Optical Drive] ***************
2026-03-13 10:11:38.747254 | controller | Friday 13 March 2026  10:11:38 +0000 (0:00:10.028)       0:00:49.776 **********
2026-03-13 10:11:38.747264 | controller | ok: [instance]
2026-03-13 10:11:38.747511 | controller |
2026-03-13 10:11:38.747545 | controller | TASK [reproducer : Verify boot override was applied] ***************************
2026-03-13 10:11:39.018230 | controller | Friday 13 March 2026  10:11:38 +0000 (0:00:00.289)       0:00:50.066 **********
2026-03-13 10:11:39.018272 | controller | ok: [instance]
2026-03-13 10:11:39.018282 | controller |
2026-03-13 10:11:39.018289 | controller | TASK [reproducer : Assert boot override is set correctly] **********************
2026-03-13 10:11:39.018299 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.270)       0:00:50.337 **********
2026-03-13 10:11:39.042191 | controller | ok: [instance] => {
2026-03-13 10:11:39.042246 | controller |     "changed": false,
2026-03-13 10:11:39.042255 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:39.042264 | controller | }
2026-03-13 10:11:39.042523 | controller |
2026-03-13 10:11:39.318099 | controller | TASK [reproducer : Verify VirtualMedia is still inserted] **********************
2026-03-13 10:11:39.318189 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.024)       0:00:50.361 **********
2026-03-13 10:11:39.318214 | controller | ok: [instance]
2026-03-13 10:11:39.318458 | controller |
2026-03-13 10:11:39.318595 | controller | TASK [reproducer : Assert VirtualMedia ISO is mounted] *************************
2026-03-13 10:11:39.318726 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.276)       0:00:50.637 **********
2026-03-13 10:11:39.351632 | controller | ok: [instance] => {
2026-03-13 10:11:39.351904 | controller |     "changed": false,
2026-03-13 10:11:39.352205 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:39.352457 | controller | }
2026-03-13 10:11:39.352599 | controller |
2026-03-13 10:11:39.352725 | controller | TASK [Query mock state] ********************************************************
2026-03-13 10:11:39.352849 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.033)       0:00:50.671 **********
2026-03-13 10:11:39.625460 | controller | ok: [instance]
2026-03-13 10:11:39.625720 | controller |
2026-03-13 10:11:39.625977 | controller | TASK [Assert boot override set with user-provided path] ************************
2026-03-13 10:11:39.626145 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.273)       0:00:50.944 **********
2026-03-13 10:11:39.646279 | controller | ok: [instance] => {
2026-03-13 10:11:39.646561 | controller |     "changed": false,
2026-03-13 10:11:39.646816 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:39.647044 | controller | }
2026-03-13 10:11:39.647204 | controller |
2026-03-13 10:11:39.647337 | controller | TASK [Reset mock with VirtualMedia inserted] ***********************************
2026-03-13 10:11:39.647471 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.020)       0:00:50.965 **********
2026-03-13 10:11:39.915522 | controller | ok: [instance]
2026-03-13 10:11:39.915690 | controller |
2026-03-13 10:11:39.915830 | controller | TASK [Include bm_discover_vmedia_target with invalid path (expect failure)] ****
2026-03-13 10:11:39.915960 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.269)       0:00:51.234 **********
2026-03-13 10:11:39.947032 | controller |
2026-03-13 10:11:39.947373 | controller | TASK [reproducer : Fetch UEFI boot option IDs] *********************************
2026-03-13 10:11:39.947621 | controller | Friday 13 March 2026  10:11:39 +0000 (0:00:00.031)       0:00:51.266 **********
2026-03-13 10:11:40.218216 | controller | ok: [instance]
2026-03-13 10:11:40.218286 | controller |
2026-03-13 10:11:40.218297 | controller | TASK [reproducer : Fetch each UEFI boot option detail] *************************
2026-03-13 10:11:40.218308 | controller | Friday 13 March 2026  10:11:40 +0000 (0:00:00.271)       0:00:51.537 **********
2026-03-13 10:11:41.511244 | controller | ok: [instance] => (item=Boot0001)
2026-03-13 10:11:41.511290 | controller | ok: [instance] => (item=Boot0003)
2026-03-13 10:11:41.511298 | controller | ok: [instance] => (item=Boot0004)
2026-03-13 10:11:41.511304 | controller | ok: [instance] => (item=Boot0005)
2026-03-13 10:11:41.511310 | controller | ok: [instance] => (item=Boot0006)
2026-03-13 10:11:41.511315 | controller |
2026-03-13 10:11:41.511321 | controller | TASK [reproducer : Build list of known UEFI device paths] **********************
2026-03-13 10:11:41.511329 | controller | Friday 13 March 2026  10:11:41 +0000 (0:00:01.291)       0:00:52.829 **********
2026-03-13 10:11:41.546211 | controller | ok: [instance]
2026-03-13 10:11:41.546254 | controller |
2026-03-13 10:11:41.546266 | controller | TASK [reproducer : Validate user-provided VirtualMedia UEFI path] **************
2026-03-13 10:11:41.546367 | controller | Friday 13 March 2026  10:11:41 +0000 (0:00:00.036)       0:00:52.865 **********
2026-03-13 10:11:41.582052 | controller | fatal: [instance]: FAILED! => {
2026-03-13 10:11:41.586257 | controller |     "assertion": "cifmw_bm_agent_vmedia_uefi_path in _known_uefi_paths",
2026-03-13 10:11:41.586281 | controller |     "changed": false,
2026-03-13 10:11:41.586290 | controller |     "evaluated_to": false,
2026-03-13 10:11:41.586298 | 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-13 10:11:41.586306 | controller | }
2026-03-13 10:11:41.586317 | controller |
2026-03-13 10:11:41.586444 | controller | TASK [Assert failure was about UEFI path] **************************************
2026-03-13 10:11:41.586479 | controller | Friday 13 March 2026  10:11:41 +0000 (0:00:00.039)       0:00:52.905 **********
2026-03-13 10:11:41.624237 | controller | ok: [instance] => {
2026-03-13 10:11:41.624259 | controller |     "changed": false,
2026-03-13 10:11:41.624268 | controller |     "msg": "All assertions passed"
2026-03-13 10:11:41.624275 | controller | }
2026-03-13 10:11:41.624281 | controller |
2026-03-13 10:11:41.624287 | controller | PLAY RECAP *********************************************************************
2026-03-13 10:11:41.624294 | controller | instance                   : ok=110  changed=0    unreachable=0    failed=0    skipped=12   rescued=5    ignored=0
2026-03-13 10:11:41.624303 | controller |
2026-03-13 10:11:41.624388 | controller | Friday 13 March 2026  10:11:41 +0000 (0:00:00.037)       0:00:52.942 **********
2026-03-13 10:11:41.624525 | controller | ===============================================================================
2026-03-13 10:11:41.624583 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-13 10:11:41.624689 | controller | reproducer : Wait for iDRAC to settle after clearing jobs -------------- 10.03s
2026-03-13 10:11:41.624781 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-13 10:11:41.624863 | controller | reproducer : Wait for VirtualMedia eject to settle ---------------------- 5.03s
2026-03-13 10:11:41.624957 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.35s
2026-03-13 10:11:41.625048 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.31s
2026-03-13 10:11:41.625169 | controller | reproducer : Fetch each UEFI boot option detail ------------------------- 1.29s
2026-03-13 10:11:41.625281 | controller | Reset mock to power Off ------------------------------------------------- 0.39s
2026-03-13 10:11:41.625388 | controller | Reset mock with usb_boot Enabled and host Off --------------------------- 0.29s
2026-03-13 10:11:41.625489 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.29s
2026-03-13 10:11:41.625596 | controller | reproducer : Set one-time boot from Virtual Optical Drive --------------- 0.29s
2026-03-13 10:11:41.625696 | controller | Reset mock with usb_boot Disabled and host Off -------------------------- 0.29s
2026-03-13 10:11:41.625787 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.29s
2026-03-13 10:11:41.625890 | controller | Query mock state -------------------------------------------------------- 0.29s
2026-03-13 10:11:41.625992 | controller | reproducer : Query current power state ---------------------------------- 0.29s
2026-03-13 10:11:41.626092 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.29s
2026-03-13 10:11:41.626220 | controller | reproducer : Clear pending iDRAC config jobs that block boot override --- 0.28s
2026-03-13 10:11:41.626329 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.28s
2026-03-13 10:11:41.626429 | controller | reproducer : Clear pending iDRAC config jobs that block boot override --- 0.28s
2026-03-13 10:11:41.626529 | controller | reproducer : Read GenericUsbBoot BIOS attribute ------------------------- 0.28s
2026-03-13 10:11:41.687953 | controller | INFO     Running bm_redfish > cleanup
2026-03-13 10:11:42.073083 | controller |
2026-03-13 10:11:42.073392 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-13 10:11:42.073598 | controller |
2026-03-13 10:11:42.073802 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-13 10:11:42.073959 | controller | Friday 13 March 2026  10:11:42 +0000 (0:00:00.021)       0:00:00.021 **********
2026-03-13 10:11:42.341514 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.013425", "end": "2026-03-13 10:11:42.319724", "msg": "non-zero return code", "rc": -15, "start": "2026-03-13 10:11:42.306299", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-13 10:11:42.342943 | controller |
2026-03-13 10:11:42.342992 | controller | PLAY RECAP *********************************************************************
2026-03-13 10:11:42.343233 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-13 10:11:42.343490 | controller |
2026-03-13 10:11:42.343510 | controller | Friday 13 March 2026  10:11:42 +0000 (0:00:00.270)       0:00:00.292 **********
2026-03-13 10:11:42.392681 | controller | ===============================================================================
2026-03-13 10:11:42.392703 | controller | Stop mock iDRAC server -------------------------------------------------- 0.27s
2026-03-13 10:11:42.392716 | 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-13 10:11:42.393104 | controller | WARNING  An error occurred during the test sequence action: 'cleanup'. Cleaning up.
2026-03-13 10:11:42.402362 | controller | INFO     Running bm_redfish > cleanup
2026-03-13 10:11:42.786227 | controller |
2026-03-13 10:11:42.786394 | controller | PLAY [Cleanup mock iDRAC server] ***********************************************
2026-03-13 10:11:42.786531 | controller |
2026-03-13 10:11:42.786672 | controller | TASK [Stop mock iDRAC server] **************************************************
2026-03-13 10:11:42.786816 | controller | Friday 13 March 2026  10:11:42 +0000 (0:00:00.022)       0:00:00.022 **********
2026-03-13 10:11:43.060265 | controller | fatal: [instance]: FAILED! => {"changed": false, "cmd": "pkill -f 'mock_idrac.py.*--port 8443' || true", "delta": "0:00:00.013212", "end": "2026-03-13 10:11:43.038742", "msg": "non-zero return code", "rc": -15, "start": "2026-03-13 10:11:43.025530", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}
2026-03-13 10:11:43.062274 | controller |
2026-03-13 10:11:43.105203 | controller | PLAY RECAP *********************************************************************
2026-03-13 10:11:43.105246 | controller | instance                   : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0
2026-03-13 10:11:43.105256 | controller |
2026-03-13 10:11:43.105265 | controller | Friday 13 March 2026  10:11:43 +0000 (0:00:00.276)       0:00:00.298 **********
2026-03-13 10:11:43.105272 | controller | ===============================================================================
2026-03-13 10:11:43.105279 | controller | Stop mock iDRAC server -------------------------------------------------- 0.28s
2026-03-13 10:11:43.105292 | 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-13 10:11:43.105403 | controller | INFO     Writing /tmp/report.html report.
2026-03-13 10:11:43.401451 | controller | ERROR
2026-03-13 10:11:43.401618 | controller | {
2026-03-13 10:11:43.401657 | controller |   "delta": "0:00:58.430171",
2026-03-13 10:11:43.401682 | controller |   "end": "2026-03-13 10:11:43.156212",
2026-03-13 10:11:43.401702 | controller |   "msg": "non-zero return code",
2026-03-13 10:11:43.401721 | controller |   "rc": 2,
2026-03-13 10:11:43.401741 | controller |   "start": "2026-03-13 10:10:44.726041"
2026-03-13 10:11:43.401760 | controller | }
failure
2026-03-13 10:11:43.446617 | 
2026-03-13 10:11:43.446670 | PLAY RECAP
2026-03-13 10:11:43.446712 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2026-03-13 10:11:43.446734 | 
2026-03-13 10:11:43.508751 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-03-13 10:11:43.509499 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-13 10:11:44.009217 | 
2026-03-13 10:11:44.009327 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-03-13 10:11:44.029957 | 
2026-03-13 10:11:44.030050 | TASK [Filter out host if needed]
2026-03-13 10:11:44.038918 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-03-13 10:11:44.043509 | 
2026-03-13 10:11:44.043577 | TASK [Ensure file is present]
2026-03-13 10:11:44.385950 | controller | ok
2026-03-13 10:11:44.392509 | 
2026-03-13 10:11:44.392575 | TASK [Manage molecule report file]
2026-03-13 10:11:44.918160 | controller | changed
2026-03-13 10:11:44.923066 | 
2026-03-13 10:11:44.923124 | TASK [Check if we get ci-framework-data basedir]
2026-03-13 10:11:45.164842 | controller | ok
2026-03-13 10:11:45.170067 | 
2026-03-13 10:11:45.170133 | TASK [Create ci-framework-data log directory for zuul]
2026-03-13 10:11:45.514455 | controller | changed
2026-03-13 10:11:45.519171 | 
2026-03-13 10:11:45.519237 | TASK [Copy ci-framework interesting files]
2026-03-13 10:11:45.758936 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory
2026-03-13 10:11:46.044118 | controller | changed
2026-03-13 10:11:46.048555 | 
2026-03-13 10:11:46.048618 | TASK [Get SELinux listing]
2026-03-13 10:11:46.572198 | controller | changed
2026-03-13 10:11:46.577514 | 
2026-03-13 10:11:46.577576 | TASK [Generate log index]
2026-03-13 10:11:47.579869 | controller | changed
2026-03-13 10:11:47.584713 | 
2026-03-13 10:11:47.584780 | TASK [Get some env related data]
2026-03-13 10:11:48.210029 | controller | /home/zuul/.local/bin/ansible
2026-03-13 10:11:49.113011 | controller | changed
2026-03-13 10:11:49.119137 | 
2026-03-13 10:11:49.119225 | TASK [Generate list of logs to collect in home directory]
2026-03-13 10:11:49.451985 | controller | ok: All paths examined
2026-03-13 10:11:49.476511 | 
2026-03-13 10:11:49.476597 | LOOP [Copy logs from home directory]
2026-03-13 10:11:49.993244 | controller | changed:
2026-03-13 10:11:49.993466 | controller | {
2026-03-13 10:11:49.993497 | controller |   "atime": 1772005405.932821,
2026-03-13 10:11:49.993517 | controller |   "ctime": 1772006396.9238591,
2026-03-13 10:11:49.993536 | controller |   "dev": 64513,
2026-03-13 10:11:49.993557 | controller |   "gid": 1000,
2026-03-13 10:11:49.993575 | controller |   "gr_name": "zuul",
2026-03-13 10:11:49.993592 | controller |   "inode": 2773,
2026-03-13 10:11:49.993608 | controller |   "isblk": false,
2026-03-13 10:11:49.993623 | controller |   "ischr": false,
2026-03-13 10:11:49.993637 | controller |   "isdir": false,
2026-03-13 10:11:49.993651 | controller |   "isfifo": false,
2026-03-13 10:11:49.993666 | controller |   "isgid": false,
2026-03-13 10:11:49.993682 | controller |   "islnk": false,
2026-03-13 10:11:49.993696 | controller |   "isreg": true,
2026-03-13 10:11:49.993710 | controller |   "issock": false,
2026-03-13 10:11:49.993724 | controller |   "isuid": false,
2026-03-13 10:11:49.993738 | controller |   "mode": "0644",
2026-03-13 10:11:49.993752 | controller |   "mtime": 1772006396.9238591,
2026-03-13 10:11:49.993766 | controller |   "nlink": 1,
2026-03-13 10:11:49.993781 | controller |   "path": "/home/zuul/crc-setup.log",
2026-03-13 10:11:49.993798 | controller |   "pw_name": "zuul",
2026-03-13 10:11:49.993813 | controller |   "rgrp": true,
2026-03-13 10:11:49.993828 | controller |   "roth": true,
2026-03-13 10:11:49.993842 | controller |   "rusr": true,
2026-03-13 10:11:49.993856 | controller |   "size": 4108,
2026-03-13 10:11:49.993869 | controller |   "uid": 1000,
2026-03-13 10:11:49.993883 | controller |   "wgrp": false,
2026-03-13 10:11:49.993896 | controller |   "woth": false,
2026-03-13 10:11:49.993912 | controller |   "wusr": true,
2026-03-13 10:11:49.993928 | controller |   "xgrp": false,
2026-03-13 10:11:49.993954 | controller |   "xoth": false,
2026-03-13 10:11:49.993969 | controller |   "xusr": false
2026-03-13 10:11:49.993983 | controller | }
2026-03-13 10:11:50.510335 | controller | changed:
2026-03-13 10:11:50.510428 | controller | {
2026-03-13 10:11:50.510477 | controller |   "atime": 1772006398.6759083,
2026-03-13 10:11:50.510507 | controller |   "ctime": 1772007098.5537844,
2026-03-13 10:11:50.510524 | controller |   "dev": 64513,
2026-03-13 10:11:50.510540 | controller |   "gid": 1000,
2026-03-13 10:11:50.510555 | controller |   "gr_name": "zuul",
2026-03-13 10:11:50.510570 | controller |   "inode": 359205,
2026-03-13 10:11:50.510584 | controller |   "isblk": false,
2026-03-13 10:11:50.510598 | controller |   "ischr": false,
2026-03-13 10:11:50.510611 | controller |   "isdir": false,
2026-03-13 10:11:50.510628 | controller |   "isfifo": false,
2026-03-13 10:11:50.510644 | controller |   "isgid": false,
2026-03-13 10:11:50.510657 | controller |   "islnk": false,
2026-03-13 10:11:50.510670 | controller |   "isreg": true,
2026-03-13 10:11:50.510684 | controller |   "issock": false,
2026-03-13 10:11:50.510696 | controller |   "isuid": false,
2026-03-13 10:11:50.510709 | controller |   "mode": "0644",
2026-03-13 10:11:50.510722 | controller |   "mtime": 1772007098.5537844,
2026-03-13 10:11:50.510735 | controller |   "nlink": 1,
2026-03-13 10:11:50.510750 | controller |   "path": "/home/zuul/crc-start.log",
2026-03-13 10:11:50.510765 | controller |   "pw_name": "zuul",
2026-03-13 10:11:50.510779 | controller |   "rgrp": true,
2026-03-13 10:11:50.510792 | controller |   "roth": true,
2026-03-13 10:11:50.510806 | controller |   "rusr": true,
2026-03-13 10:11:50.510819 | controller |   "size": 4654,
2026-03-13 10:11:50.510832 | controller |   "uid": 1000,
2026-03-13 10:11:50.510845 | controller |   "wgrp": false,
2026-03-13 10:11:50.510858 | controller |   "woth": false,
2026-03-13 10:11:50.510871 | controller |   "wusr": true,
2026-03-13 10:11:50.510883 | controller |   "xgrp": false,
2026-03-13 10:11:50.510896 | controller |   "xoth": false,
2026-03-13 10:11:50.510908 | controller |   "xusr": false
2026-03-13 10:11:50.510921 | controller | }
2026-03-13 10:11:51.036153 | controller | changed:
2026-03-13 10:11:51.036210 | controller | {
2026-03-13 10:11:51.036234 | controller |   "atime": 1773396626.5548823,
2026-03-13 10:11:51.036253 | controller |   "ctime": 1773396642.3872042,
2026-03-13 10:11:51.036268 | controller |   "dev": 64513,
2026-03-13 10:11:51.036288 | controller |   "gid": 1000,
2026-03-13 10:11:51.036324 | controller |   "gr_name": "zuul",
2026-03-13 10:11:51.036341 | controller |   "inode": 1189020,
2026-03-13 10:11:51.036355 | controller |   "isblk": false,
2026-03-13 10:11:51.036369 | controller |   "ischr": false,
2026-03-13 10:11:51.036382 | controller |   "isdir": false,
2026-03-13 10:11:51.036395 | controller |   "isfifo": false,
2026-03-13 10:11:51.036408 | controller |   "isgid": false,
2026-03-13 10:11:51.036422 | controller |   "islnk": false,
2026-03-13 10:11:51.036434 | controller |   "isreg": true,
2026-03-13 10:11:51.036448 | controller |   "issock": false,
2026-03-13 10:11:51.036461 | controller |   "isuid": false,
2026-03-13 10:11:51.036473 | controller |   "mode": "0644",
2026-03-13 10:11:51.036487 | controller |   "mtime": 1773396642.3872042,
2026-03-13 10:11:51.036501 | controller |   "nlink": 1,
2026-03-13 10:11:51.036514 | controller |   "path": "/home/zuul/ansible.log",
2026-03-13 10:11:51.036528 | controller |   "pw_name": "zuul",
2026-03-13 10:11:51.036541 | controller |   "rgrp": true,
2026-03-13 10:11:51.036555 | controller |   "roth": true,
2026-03-13 10:11:51.036570 | controller |   "rusr": true,
2026-03-13 10:11:51.036584 | controller |   "size": 6749,
2026-03-13 10:11:51.036596 | controller |   "uid": 1000,
2026-03-13 10:11:51.036609 | controller |   "wgrp": false,
2026-03-13 10:11:51.036621 | controller |   "woth": false,
2026-03-13 10:11:51.036633 | controller |   "wusr": true,
2026-03-13 10:11:51.036645 | controller |   "xgrp": false,
2026-03-13 10:11:51.036657 | controller |   "xoth": false,
2026-03-13 10:11:51.036668 | controller |   "xusr": false
2026-03-13 10:11:51.036680 | controller | }
2026-03-13 10:11:51.051572 | 
2026-03-13 10:11:51.051682 | TASK [Copy crio stats log file]
2026-03-13 10:11:51.065416 | controller | skipping: Conditional result was False
2026-03-13 10:11:51.070288 | 
2026-03-13 10:11:51.070364 | TASK [Get SELinux related data]
2026-03-13 10:11:51.327442 | controller | <no matches>
2026-03-13 10:11:51.593520 | controller | ERROR
2026-03-13 10:11:51.593717 | controller | {
2026-03-13 10:11:51.593751 | controller |   "delta": "0:00:00.009539",
2026-03-13 10:11:51.593774 | controller |   "end": "2026-03-13 10:11:51.328471",
2026-03-13 10:11:51.593794 | controller |   "msg": "non-zero return code",
2026-03-13 10:11:51.593811 | controller |   "rc": 1,
2026-03-13 10:11:51.593828 | controller |   "start": "2026-03-13 10:11:51.318932"
2026-03-13 10:11:51.593844 | controller | }
2026-03-13 10:11:51.593865 | controller | ERROR: Ignoring Errors
2026-03-13 10:11:51.598414 | 
2026-03-13 10:11:51.598473 | TASK [Create system configuration directory]
2026-03-13 10:11:51.849756 | controller | changed
2026-03-13 10:11:51.854375 | 
2026-03-13 10:11:51.854442 | TASK [Get some of the system configurations]
2026-03-13 10:11:52.379387 | controller | changed
2026-03-13 10:11:52.384153 | 
2026-03-13 10:11:52.384216 | TASK [Copy generated documentation if available]
2026-03-13 10:11:52.397556 | controller | skipping: Conditional result was False
2026-03-13 10:11:52.402879 | 
2026-03-13 10:11:52.402954 | TASK [Copy generated AsciiDoc documentation if available]
2026-03-13 10:11:52.416054 | controller | skipping: Conditional result was False
2026-03-13 10:11:52.421381 | 
2026-03-13 10:11:52.421443 | TASK [Compress logs bigger than 2MB]
2026-03-13 10:11:52.947401 | controller | changed
2026-03-13 10:11:52.952270 | 
2026-03-13 10:11:52.952342 | TASK [Copy files from workspace on node]
2026-03-13 10:11:52.969282 | controller | ok
2026-03-13 10:11:52.988633 | 
2026-03-13 10:11:52.988696 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-13 10:11:53.001111 | controller | skipping: Conditional result was False
2026-03-13 10:11:53.006081 | 
2026-03-13 10:11:53.006143 | TASK [fetch-output : Set log path for single node]
2026-03-13 10:11:53.023613 | controller | ok
2026-03-13 10:11:53.027918 | 
2026-03-13 10:11:53.027985 | LOOP [fetch-output : Ensure local output dirs]
2026-03-13 10:11:53.203850 | controller -> localhost | ok: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/logs"
2026-03-13 10:11:53.204068 | controller -> localhost | changed: All items complete
2026-03-13 10:11:53.204100 | 
2026-03-13 10:11:53.365817 | controller -> localhost | changed: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/artifacts"
2026-03-13 10:11:53.534430 | controller -> localhost | changed: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/docs"
2026-03-13 10:11:53.543052 | 
2026-03-13 10:11:53.543132 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-13 10:11:54.123363 | controller | changed:
2026-03-13 10:11:54.123594 | controller | .d..t...... ./
2026-03-13 10:11:54.123630 | controller | >f+++++++++ README.html
2026-03-13 10:11:54.123654 | controller | >f+++++++++ ansible-execution.log
2026-03-13 10:11:54.123677 | controller | >f+++++++++ ansible.log
2026-03-13 10:11:54.123697 | controller | >f+++++++++ crc-setup.log
2026-03-13 10:11:54.123715 | controller | >f+++++++++ crc-start.log
2026-03-13 10:11:54.123732 | controller | >f+++++++++ dmesg.log
2026-03-13 10:11:54.123753 | controller | >f+++++++++ installed-pkgs.log
2026-03-13 10:11:54.123771 | controller | >f+++++++++ python.log
2026-03-13 10:11:54.123788 | controller | >f+++++++++ registries.conf
2026-03-13 10:11:54.123804 | controller | >f+++++++++ report.html
2026-03-13 10:11:54.123821 | controller | >f+++++++++ selinux-denials.log
2026-03-13 10:11:54.123837 | controller | >f+++++++++ selinux-listing.log
2026-03-13 10:11:54.123853 | controller | cd+++++++++ ci-framework-data/
2026-03-13 10:11:54.123870 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-03-13 10:11:54.123888 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-03-13 10:11:54.123905 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-03-13 10:11:54.123921 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-03-13 10:11:54.123949 | controller | cd+++++++++ ci-framework-data/logs/
2026-03-13 10:11:54.123967 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-03-13 10:11:54.123984 | controller | cd+++++++++ registries.conf.d/
2026-03-13 10:11:54.124000 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-03-13 10:11:54.124017 | controller | cd+++++++++ system-config/
2026-03-13 10:11:54.124034 | controller | cd+++++++++ system-config/libvirt/
2026-03-13 10:11:54.124051 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-03-13 10:11:54.124068 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-03-13 10:11:54.124085 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2026-03-13 10:11:54.124100 | controller | >f+++++++++ system-config/libvirt/network.conf
2026-03-13 10:11:54.124116 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2026-03-13 10:11:54.124132 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2026-03-13 10:11:54.124148 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2026-03-13 10:11:54.124164 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2026-03-13 10:11:54.124182 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2026-03-13 10:11:54.124199 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2026-03-13 10:11:54.124216 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2026-03-13 10:11:54.124232 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2026-03-13 10:11:54.124249 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2026-03-13 10:11:54.124265 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2026-03-13 10:11:54.124281 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2026-03-13 10:11:54.124324 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2026-03-13 10:11:54.539340 | controller | changed: .d..t...... ./
2026-03-13 10:11:54.955950 | controller | changed: .d..t...... ./
2026-03-13 10:11:54.973289 | 
2026-03-13 10:11:54.973375 | TASK [Return artifact to Zuul]
2026-03-13 10:11:55.000873 | controller | ok
2026-03-13 10:11:55.018783 | 
2026-03-13 10:11:55.018838 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-03-13 10:11:55.018941 | 
2026-03-13 10:11:55.018970 | PLAY RECAP
2026-03-13 10:11:55.019008 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-03-13 10:11:55.019031 | 
2026-03-13 10:11:55.087160 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-03-13 10:11:55.087806 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-13 10:11:55.588182 | 
2026-03-13 10:11:55.588320 | PLAY [all]
2026-03-13 10:11:55.606241 | 
2026-03-13 10:11:55.606325 | TASK [include_role : fetch-output]
2026-03-13 10:11:55.634357 | controller | ok
2026-03-13 10:11:55.650579 | 
2026-03-13 10:11:55.650659 | TASK [fetch-output : Set log path for multiple nodes]
2026-03-13 10:11:55.684275 | controller | skipping: Conditional result was False
2026-03-13 10:11:55.690120 | 
2026-03-13 10:11:55.690196 | TASK [fetch-output : Set log path for single node]
2026-03-13 10:11:55.717608 | controller | ok
2026-03-13 10:11:55.722818 | 
2026-03-13 10:11:55.722897 | LOOP [fetch-output : Ensure local output dirs]
2026-03-13 10:11:56.031066 | controller -> localhost | ok: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/logs"
2026-03-13 10:11:56.210794 | controller -> localhost | ok: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/artifacts"
2026-03-13 10:11:56.387474 | controller -> localhost | ok: "/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/docs"
2026-03-13 10:11:56.400246 | 
2026-03-13 10:11:56.400330 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-03-13 10:11:56.969801 | controller | ok
2026-03-13 10:11:56.969976 | controller | ok: All items complete
2026-03-13 10:11:56.970007 | 
2026-03-13 10:11:57.394357 | controller | ok
2026-03-13 10:11:57.809574 | controller | ok
2026-03-13 10:11:57.821489 | 
2026-03-13 10:11:57.821552 | TASK [include_role : fetch-output-openshift]
2026-03-13 10:11:57.834232 | controller | skipping: Conditional result was False
2026-03-13 10:11:57.839451 | 
2026-03-13 10:11:57.839514 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-03-13 10:11:58.156193 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.005950
2026-03-13 10:11:58.331746 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006064
2026-03-13 10:11:58.361363 | 
2026-03-13 10:11:58.361450 | PLAY [all]
2026-03-13 10:11:58.374278 | 
2026-03-13 10:11:58.374393 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-03-13 10:11:58.838614 | controller | changed
2026-03-13 10:11:58.858158 | 
2026-03-13 10:11:58.858209 | PLAY RECAP
2026-03-13 10:11:58.858254 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-03-13 10:11:58.858277 | 
2026-03-13 10:11:58.923511 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-03-13 10:11:58.924205 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-03-13 10:11:59.423077 | 
2026-03-13 10:11:59.423218 | PLAY [localhost]
2026-03-13 10:11:59.438972 | 
2026-03-13 10:11:59.439040 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-03-13 10:11:59.719441 | localhost | changed
2026-03-13 10:11:59.723856 | 
2026-03-13 10:11:59.723946 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-03-13 10:11:59.740876 | localhost | ok
2026-03-13 10:11:59.747977 | 
2026-03-13 10:11:59.748043 | TASK [add-fileserver : Create SSH private key tempfile]
2026-03-13 10:12:00.017549 | localhost | changed
2026-03-13 10:12:00.022784 | 
2026-03-13 10:12:00.022854 | TASK [add-fileserver : Create SSH private key from secret]
2026-03-13 10:12:00.514997 | localhost | changed
2026-03-13 10:12:00.519501 | 
2026-03-13 10:12:00.519571 | TASK [add-fileserver : Add fileserver ssh key]
2026-03-13 10:12:00.819929 | localhost | Identity added: /var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/tmp/ansible.ftcnxarl (/var/lib/zuul/builds/df938b3a65c64cca900875da078e3a19/work/tmp/ansible.ftcnxarl)
2026-03-13 10:12:00.820075 | localhost | ok: Runtime: 0:00:00.006164
2026-03-13 10:12:00.823942 | 
2026-03-13 10:12:00.824006 | TASK [add-fileserver : Remove SSH private key from disk]
2026-03-13 10:12:01.022913 | localhost | ok: Runtime: 0:00:00.003445
2026-03-13 10:12:01.027074 | 
2026-03-13 10:12:01.027134 | TASK [add-fileserver : Add fileserver to inventory]
2026-03-13 10:12:01.074279 | localhost | changed
2026-03-13 10:12:01.078772 | 
2026-03-13 10:12:01.078833 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-03-13 10:12:01.370049 | localhost | changed
2026-03-13 10:12:01.389540 | 
2026-03-13 10:12:01.389645 | PLAY [localhost]
2026-03-13 10:12:01.399962 | 
2026-03-13 10:12:01.400026 | TASK [Generate bulk log download script]
2026-03-13 10:12:01.417458 | localhost | ok
2026-03-13 10:12:01.427631 | 
2026-03-13 10:12:01.427693 | TASK [local-log-download : Check API endpoint is defined]
2026-03-13 10:12:01.453855 | localhost | ok: All assertions passed
2026-03-13 10:12:01.457824 | 
2026-03-13 10:12:01.457883 | TASK [local-log-download : Create download script]
2026-03-13 10:12:01.773785 | localhost -> localhost | changed
2026-03-13 10:12:01.781769 | 
2026-03-13 10:12:01.781839 | TASK [Register quick-download link]
2026-03-13 10:12:01.797793 | localhost | ok
2026-03-13 10:12:01.828501 | 
2026-03-13 10:12:01.828564 | PLAY [logserver.rdoproject.org]
2026-03-13 10:12:01.837139 | 
2026-03-13 10:12:01.837195 | TASK [Set zuul-log-path fact]
2026-03-13 10:12:01.852197 | logserver.rdoproject.org | ok
2026-03-13 10:12:01.860062 | 
2026-03-13 10:12:01.860121 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-03-13 10:12:01.874923 | logserver.rdoproject.org | ok
2026-03-13 10:12:01.879699 | 
2026-03-13 10:12:01.879760 | TASK [upload-logs : Create log directories]
2026-03-13 10:12:03.725680 | logserver.rdoproject.org | changed
2026-03-13 10:12:03.728654 | 
2026-03-13 10:12:03.728718 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-03-13 10:12:03.925077 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004593
2026-03-13 10:12:03.929237 | 
2026-03-13 10:12:03.929313 | TASK [upload-logs : Upload logs to log server]
2026-03-13 10:12:05.347159 | logserver.rdoproject.org | Output suppressed because no_log was given
2026-03-13 10:12:05.349878 | 
2026-03-13 10:12:05.349950 | LOOP [upload-logs : Compress console log and json output]
2026-03-13 10:12:05.385246 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-13 10:12:05.394469 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-13 10:12:05.406799 | 
2026-03-13 10:12:05.406878 | LOOP [upload-logs : Upload compressed console log and json output]
2026-03-13 10:12:05.441122 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-13 10:12:05.441338 | 
2026-03-13 10:12:05.445509 | logserver.rdoproject.org | skipping: Conditional result was False
2026-03-13 10:12:05.453562 | 
2026-03-13 10:12:05.453635 | LOOP [upload-logs : Upload console log and json output]