2026-01-20 22:35:37.972726 | Job console starting...
2026-01-20 22:35:38.533906 | Updating repositories
2026-01-20 22:35:39.258247 | Preparing job workspace
2026-01-20 22:35:48.621925 | Running Ansible setup...
2026-01-20 22:35:52.445381 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-01-20 22:35:52.976323 | 
2026-01-20 22:35:52.976435 | PLAY [localhost]
2026-01-20 22:35:52.985700 | 
2026-01-20 22:35:52.985783 | TASK [Gathering Facts]
2026-01-20 22:35:53.819383 | localhost | ok
2026-01-20 22:35:53.833105 | 
2026-01-20 22:35:53.833190 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-20 22:35:54.186558 | localhost -> localhost | changed
2026-01-20 22:35:54.192056 | 
2026-01-20 22:35:54.192132 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-20 22:35:54.989619 | localhost -> localhost | changed
2026-01-20 22:35:54.997933 | 
2026-01-20 22:35:54.998027 | TASK [Setup log path fact]
2026-01-20 22:35:55.016101 | localhost | ok
2026-01-20 22:35:55.028633 | 
2026-01-20 22:35:55.028741 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-20 22:35:55.056481 | localhost | ok
2026-01-20 22:35:55.067259 | 
2026-01-20 22:35:55.067394 | TASK [emit-job-header : Print job information]
2026-01-20 22:35:55.096138 | # Job Information
2026-01-20 22:35:55.096266 | Ansible Version: 2.15.12
2026-01-20 22:35:55.096321 | Job: cifmw-molecule-sushy_emulator
2026-01-20 22:35:55.096351 | Pipeline: github-check
2026-01-20 22:35:55.096374 | Executor: ibm-bm4-ze.softwarefactory-project.io
2026-01-20 22:35:55.096395 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3451
2026-01-20 22:35:55.096417 | Log URL (when completed): https://logserver.rdoproject.org/777/rdoproject.org/77738fc4868e49afac75e1b1c886952e/
2026-01-20 22:35:55.096438 | Event ID: 7da044b0-f64f-11f0-8db9-81cfa63b57a5
2026-01-20 22:35:55.099967 | 
2026-01-20 22:35:55.100032 | LOOP [emit-job-header : Print node information]
2026-01-20 22:35:55.188530 | localhost | ok:
2026-01-20 22:35:55.188696 | localhost | # Node Information
2026-01-20 22:35:55.188728 | localhost | Inventory Hostname: controller
2026-01-20 22:35:55.188755 | localhost | Hostname: np0005589570
2026-01-20 22:35:55.188777 | localhost | Username: zuul
2026-01-20 22:35:55.188799 | localhost | Distro: CentOS 9
2026-01-20 22:35:55.188818 | localhost | Provider: ibm-bm4-nodepool
2026-01-20 22:35:55.188838 | localhost | Region: regionOne
2026-01-20 22:35:55.188857 | localhost | Label: centos-9-stream-crc-2-48-0-xl-ibm
2026-01-20 22:35:55.188875 | localhost | Product Name: OpenStack Compute
2026-01-20 22:35:55.188894 | localhost | Interface IP: 192.168.26.197
2026-01-20 22:35:55.219094 | 
2026-01-20 22:35:55.219164 | PLAY [all]
2026-01-20 22:35:55.227359 | 
2026-01-20 22:35:55.227430 | TASK [Gather network facts]
2026-01-20 22:35:55.664647 | controller | ok
2026-01-20 22:35:55.683338 | 
2026-01-20 22:35:55.683427 | TASK [include_role : start-zuul-console]
2026-01-20 22:35:55.703140 | controller | ok
2026-01-20 22:35:55.716066 | 
2026-01-20 22:35:55.716142 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-20 22:35:56.128660 | controller | ok
2026-01-20 22:35:56.149637 | 
2026-01-20 22:35:56.149721 | TASK [include_role : add-build-sshkey]
2026-01-20 22:35:56.210731 | controller | ok
2026-01-20 22:35:56.233198 | 
2026-01-20 22:35:56.233309 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-20 22:35:56.464966 | controller -> localhost | ok
2026-01-20 22:35:56.470956 | 
2026-01-20 22:35:56.471061 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-20 22:35:56.500686 | controller | ok
2026-01-20 22:35:56.513776 | controller | included: /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-20 22:35:56.519446 | 
2026-01-20 22:35:56.519514 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-20 22:35:57.021648 | controller -> localhost | Generating public/private rsa key pair.
2026-01-20 22:35:57.021882 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/77738fc4868e49afac75e1b1c886952e_id_rsa.
2026-01-20 22:35:57.021923 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/77738fc4868e49afac75e1b1c886952e_id_rsa.pub.
2026-01-20 22:35:57.021951 | controller -> localhost | The key fingerprint is:
2026-01-20 22:35:57.021974 | controller -> localhost | SHA256:DPazKgv7127/GK443bLL23g8/tLVmxf8TqpevKniMwE zuul-build-sshkey
2026-01-20 22:35:57.022003 | controller -> localhost | The key's randomart image is:
2026-01-20 22:35:57.022026 | controller -> localhost | +---[RSA 3072]----+
2026-01-20 22:35:57.022060 | controller -> localhost | |                 |
2026-01-20 22:35:57.022083 | controller -> localhost | |                 |
2026-01-20 22:35:57.022104 | controller -> localhost | |      o          |
2026-01-20 22:35:57.022124 | controller -> localhost | |     . +E        |
2026-01-20 22:35:57.022143 | controller -> localhost | |        S.    .. |
2026-01-20 22:35:57.022163 | controller -> localhost | |         o.  ..o.|
2026-01-20 22:35:57.022182 | controller -> localhost | |  .    o.o.o .o *|
2026-01-20 22:35:57.022203 | controller -> localhost | |   o. o+=+Xo.. Bo|
2026-01-20 22:35:57.022222 | controller -> localhost | |  ..o+o+O@BX*o+.o|
2026-01-20 22:35:57.022240 | controller -> localhost | +----[SHA256]-----+
2026-01-20 22:35:57.022287 | controller -> localhost | ok: Runtime: 0:00:00.133449
2026-01-20 22:35:57.027962 | 
2026-01-20 22:35:57.028027 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-20 22:35:57.047077 | controller | ok
2026-01-20 22:35:57.056740 | controller | included: /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-20 22:35:57.066888 | 
2026-01-20 22:35:57.067089 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-20 22:35:57.090937 | controller | skipping: Conditional result was False
2026-01-20 22:35:57.097056 | 
2026-01-20 22:35:57.097134 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-20 22:35:57.665858 | controller | changed
2026-01-20 22:35:57.671087 | 
2026-01-20 22:35:57.671166 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-20 22:35:57.934146 | controller | ok
2026-01-20 22:35:57.940460 | 
2026-01-20 22:35:57.940546 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-20 22:35:59.075460 | controller | changed
2026-01-20 22:35:59.080600 | 
2026-01-20 22:35:59.080687 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-20 22:36:00.278730 | controller | changed
2026-01-20 22:36:00.286960 | 
2026-01-20 22:36:00.287114 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-20 22:36:00.315835 | controller | skipping: Conditional result was False
2026-01-20 22:36:00.321748 | 
2026-01-20 22:36:00.321841 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-20 22:36:00.784994 | controller -> localhost | changed
2026-01-20 22:36:00.795056 | 
2026-01-20 22:36:00.795123 | TASK [add-build-sshkey : Add back temp key]
2026-01-20 22:36:01.062226 | controller -> localhost | Identity added: /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/77738fc4868e49afac75e1b1c886952e_id_rsa (zuul-build-sshkey)
2026-01-20 22:36:01.062535 | controller -> localhost | ok: Runtime: 0:00:00.023496
2026-01-20 22:36:01.068480 | 
2026-01-20 22:36:01.068549 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-20 22:36:01.454446 | controller | ok
2026-01-20 22:36:01.459806 | 
2026-01-20 22:36:01.459891 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-20 22:36:01.490120 | controller | skipping: Conditional result was False
2026-01-20 22:36:01.510667 | 
2026-01-20 22:36:01.510759 | TASK [include_role : validate-host]
2026-01-20 22:36:01.529315 | controller | ok
2026-01-20 22:36:01.549474 | 
2026-01-20 22:36:01.549568 | TASK [validate-host : Define zuul_info_dir fact]
2026-01-20 22:36:01.578402 | controller | ok
2026-01-20 22:36:01.583776 | 
2026-01-20 22:36:01.583869 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2026-01-20 22:36:01.800662 | controller -> localhost | ok
2026-01-20 22:36:01.808672 | 
2026-01-20 22:36:01.808765 | TASK [validate-host : Collect information about the host]
2026-01-20 22:36:02.602669 | controller | ok
2026-01-20 22:36:02.620083 | 
2026-01-20 22:36:02.620227 | TASK [validate-host : Sanitize hostname]
2026-01-20 22:36:02.684590 | controller | ok
2026-01-20 22:36:02.693866 | 
2026-01-20 22:36:02.693953 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2026-01-20 22:36:03.199456 | controller -> localhost | changed
2026-01-20 22:36:03.205830 | 
2026-01-20 22:36:03.205904 | TASK [validate-host : Collect information about zuul worker]
2026-01-20 22:36:03.617765 | controller | ok
2026-01-20 22:36:03.627060 | 
2026-01-20 22:36:03.627162 | TASK [validate-host : Write out all zuul information for each host]
2026-01-20 22:36:04.178001 | controller -> localhost | changed
2026-01-20 22:36:04.187871 | 
2026-01-20 22:36:04.187955 | TASK [include_role : prepare-workspace-openshift]
2026-01-20 22:36:04.202012 | controller | skipping: Conditional result was False
2026-01-20 22:36:04.211382 | 
2026-01-20 22:36:04.211463 | TASK [include_role : remove-zuul-sshkey]
2026-01-20 22:36:04.224712 | controller | skipping: Conditional result was False
2026-01-20 22:36:04.231349 | 
2026-01-20 22:36:04.231446 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-20 22:36:04.520134 | controller | ok: "logs"
2026-01-20 22:36:04.520378 | controller | ok: All items complete
2026-01-20 22:36:04.520411 | 
2026-01-20 22:36:04.758320 | controller | ok: "artifacts"
2026-01-20 22:36:05.006761 | controller | ok: "docs"
2026-01-20 22:36:05.021014 | 
2026-01-20 22:36:05.021171 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-20 22:36:05.296992 | controller | changed: "logs"
2026-01-20 22:36:05.538524 | controller | changed: "artifacts"
2026-01-20 22:36:05.798687 | controller | changed: "docs"
2026-01-20 22:36:05.829061 | 
2026-01-20 22:36:05.829135 | PLAY RECAP
2026-01-20 22:36:05.829180 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-01-20 22:36:05.829209 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-20 22:36:05.829229 | 
2026-01-20 22:36:06.005776 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2026-01-20 22:36:06.006493 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-01-20 22:36:06.638435 | 
2026-01-20 22:36:06.638545 | PLAY [all]
2026-01-20 22:36:06.659693 | 
2026-01-20 22:36:06.659787 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-01-20 22:36:06.709123 | controller | ok
2026-01-20 22:36:06.714451 | 
2026-01-20 22:36:06.714560 | TASK [mirror-info-fork : Create /etc/ci]
2026-01-20 22:36:07.171713 | controller | changed
2026-01-20 22:36:07.177411 | 
2026-01-20 22:36:07.177484 | TASK [mirror-info-fork : Install ci_mirror script]
2026-01-20 22:36:08.556945 | controller | changed
2026-01-20 22:36:08.572829 | 
2026-01-20 22:36:08.572949 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2026-01-20 22:36:09.046765 | controller | changed:
2026-01-20 22:36:09.046987 | controller | {
2026-01-20 22:36:09.047025 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2026-01-20 22:36:09.047073 | controller | }
2026-01-20 22:36:09.352220 | controller | changed:
2026-01-20 22:36:09.352350 | controller | {
2026-01-20 22:36:09.352385 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2026-01-20 22:36:09.352409 | controller | }
2026-01-20 22:36:09.688537 | controller | changed:
2026-01-20 22:36:09.688633 | controller | {
2026-01-20 22:36:09.688662 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2026-01-20 22:36:09.688684 | controller | }
2026-01-20 22:36:09.995784 | controller | changed:
2026-01-20 22:36:09.995866 | controller | {
2026-01-20 22:36:09.995895 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2026-01-20 22:36:09.995916 | controller | }
2026-01-20 22:36:10.300502 | controller | changed:
2026-01-20 22:36:10.300593 | controller | {
2026-01-20 22:36:10.300623 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2026-01-20 22:36:10.300647 | controller | }
2026-01-20 22:36:10.599550 | controller | changed:
2026-01-20 22:36:10.599640 | controller | {
2026-01-20 22:36:10.599677 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2026-01-20 22:36:10.599702 | controller | }
2026-01-20 22:36:10.913767 | controller | changed:
2026-01-20 22:36:10.913865 | controller | {
2026-01-20 22:36:10.913895 | 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-01-20 22:36:10.913922 | controller | }
2026-01-20 22:36:11.213386 | controller | changed:
2026-01-20 22:36:11.213519 | controller | {
2026-01-20 22:36:11.213549 | 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-01-20 22:36:11.213571 | controller | }
2026-01-20 22:36:11.518686 | controller | changed:
2026-01-20 22:36:11.518781 | controller | {
2026-01-20 22:36:11.518810 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2026-01-20 22:36:11.518831 | controller | }
2026-01-20 22:36:11.845554 | controller | changed:
2026-01-20 22:36:11.845632 | controller | {
2026-01-20 22:36:11.845659 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2026-01-20 22:36:11.845680 | controller | }
2026-01-20 22:36:12.160401 | controller | changed:
2026-01-20 22:36:12.160547 | controller | {
2026-01-20 22:36:12.160582 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2026-01-20 22:36:12.160606 | controller | }
2026-01-20 22:36:12.473943 | controller | changed:
2026-01-20 22:36:12.474035 | controller | {
2026-01-20 22:36:12.474081 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2026-01-20 22:36:12.474113 | controller | }
2026-01-20 22:36:12.803403 | controller | changed:
2026-01-20 22:36:12.803489 | controller | {
2026-01-20 22:36:12.803519 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2026-01-20 22:36:12.803541 | controller | }
2026-01-20 22:36:13.116712 | controller | changed:
2026-01-20 22:36:13.116813 | controller | {
2026-01-20 22:36:13.116845 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2026-01-20 22:36:13.116872 | controller | }
2026-01-20 22:36:13.429411 | controller | changed:
2026-01-20 22:36:13.429514 | controller | {
2026-01-20 22:36:13.429541 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2026-01-20 22:36:13.429563 | controller | }
2026-01-20 22:36:13.764438 | controller | changed:
2026-01-20 22:36:13.764529 | controller | {
2026-01-20 22:36:13.764559 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2026-01-20 22:36:13.764579 | controller | }
2026-01-20 22:36:14.087488 | controller | changed:
2026-01-20 22:36:14.087575 | controller | {
2026-01-20 22:36:14.087605 | 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-01-20 22:36:14.087628 | controller | }
2026-01-20 22:36:14.398591 | controller | changed:
2026-01-20 22:36:14.398676 | controller | {
2026-01-20 22:36:14.398705 | 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-01-20 22:36:14.398739 | controller | }
2026-01-20 22:36:14.715258 | controller | changed:
2026-01-20 22:36:14.715367 | controller | {
2026-01-20 22:36:14.715398 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2026-01-20 22:36:14.715421 | controller | }
2026-01-20 22:36:15.008816 | controller | changed:
2026-01-20 22:36:15.008939 | controller | {
2026-01-20 22:36:15.008975 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2026-01-20 22:36:15.008998 | controller | }
2026-01-20 22:36:15.326321 | controller | changed:
2026-01-20 22:36:15.326411 | controller | {
2026-01-20 22:36:15.326437 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2026-01-20 22:36:15.326457 | controller | }
2026-01-20 22:36:15.643531 | controller | changed:
2026-01-20 22:36:15.643730 | controller | {
2026-01-20 22:36:15.643771 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2026-01-20 22:36:15.643794 | controller | }
2026-01-20 22:36:15.958870 | controller | changed:
2026-01-20 22:36:15.959069 | controller | {
2026-01-20 22:36:15.959109 | 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-01-20 22:36:15.959134 | controller | }
2026-01-20 22:36:16.266941 | controller | changed:
2026-01-20 22:36:16.267022 | controller | {
2026-01-20 22:36:16.267077 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2026-01-20 22:36:16.267101 | controller | }
2026-01-20 22:36:16.579365 | controller | changed:
2026-01-20 22:36:16.579455 | controller | {
2026-01-20 22:36:16.579483 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2026-01-20 22:36:16.579504 | controller | }
2026-01-20 22:36:16.885917 | controller | changed:
2026-01-20 22:36:16.886009 | controller | {
2026-01-20 22:36:16.886058 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2026-01-20 22:36:16.886095 | controller | }
2026-01-20 22:36:16.925164 | 
2026-01-20 22:36:16.925409 | TASK [Set timezone to UTC]
2026-01-20 22:36:17.589980 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2026-01-20 22:36:17.595864 | 
2026-01-20 22:36:17.595951 | TASK [Create nodepool directory]
2026-01-20 22:36:17.895965 | controller | changed
2026-01-20 22:36:17.902465 | 
2026-01-20 22:36:17.902544 | TASK [Create nodepool sub_nodes file]
2026-01-20 22:36:18.986160 | controller | changed
2026-01-20 22:36:18.992635 | 
2026-01-20 22:36:18.992717 | TASK [Create nodepool sub_nodes_private file]
2026-01-20 22:36:20.181638 | controller | changed
2026-01-20 22:36:20.188354 | 
2026-01-20 22:36:20.188448 | LOOP [Populate nodepool sub_nodes file]
2026-01-20 22:36:20.229130 | 
2026-01-20 22:36:20.229267 | LOOP [Populate nodepool sub_nodes_private file]
2026-01-20 22:36:20.270010 | 
2026-01-20 22:36:20.270274 | TASK [Create nodepool primary file]
2026-01-20 22:36:20.317311 | controller | skipping: Conditional result was False
2026-01-20 22:36:20.324959 | 
2026-01-20 22:36:20.325076 | TASK [Create nodepool node_private for this node]
2026-01-20 22:36:21.469537 | controller | changed
2026-01-20 22:36:21.478123 | 
2026-01-20 22:36:21.478204 | LOOP [Copy ssh keys to nodepool directory]
2026-01-20 22:36:22.109932 | controller | ok: Item: id_rsa Runtime: 0:00:00.005232
2026-01-20 22:36:22.110111 | 
2026-01-20 22:36:22.358795 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005470
2026-01-20 22:36:22.375307 | 
2026-01-20 22:36:22.375412 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2026-01-20 22:36:23.614803 | controller | changed
2026-01-20 22:36:23.620382 | 
2026-01-20 22:36:23.620468 | TASK [Validate sudoers config after edits]
2026-01-20 22:36:23.972765 | controller | /etc/sudoers: parsed OK
2026-01-20 22:36:23.972939 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2026-01-20 22:36:23.972951 | controller | /etc/sudoers.d/zuul: parsed OK
2026-01-20 22:36:23.972958 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2026-01-20 22:36:24.159150 | controller | ok: Runtime: 0:00:00.006647
2026-01-20 22:36:24.164730 | 
2026-01-20 22:36:24.164799 | TASK [Show the environment passed in to job shell scripts]
2026-01-20 22:36:24.475015 | controller | SHELL=/bin/bash
2026-01-20 22:36:24.475070 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2026-01-20 22:36:24.475080 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2026-01-20 22:36:24.475087 | controller | ZUUL_CHANGES=rdo-jobs:master:refs/changes/88/58488/2^openstack-k8s-operators/ci-framework:main:refs/changes/51/3451/3b80a23c9439dd2e7554486894e6cc29bcabd667
2026-01-20 22:36:24.475103 | controller | PWD=/home/zuul
2026-01-20 22:36:24.475163 | controller | ZUUL_PIPELINE=github-check
2026-01-20 22:36:24.475172 | controller | LOGNAME=zuul
2026-01-20 22:36:24.475178 | controller | XDG_SESSION_TYPE=tty
2026-01-20 22:36:24.475183 | controller | _=/usr/bin/env
2026-01-20 22:36:24.475188 | controller | MOTD_SHOWN=pam
2026-01-20 22:36:24.475193 | controller | HOME=/home/zuul
2026-01-20 22:36:24.475198 | controller | LANG=en_US.UTF-8
2026-01-20 22:36:24.475204 | controller | SSH_CONNECTION=192.168.26.12 42684 192.168.26.197 22
2026-01-20 22:36:24.475209 | 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-01-20 22:36:24.475217 | controller | ZUUL_CHANGE_IDS=58488,2 3451,3b80a23c9439dd2e7554486894e6cc29bcabd667
2026-01-20 22:36:24.475225 | controller | WORKSPACE=/home/zuul/workspace
2026-01-20 22:36:24.475232 | controller | XDG_SESSION_CLASS=user
2026-01-20 22:36:24.475237 | controller | SELINUX_ROLE_REQUESTED=
2026-01-20 22:36:24.475242 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2026-01-20 22:36:24.475248 | controller | USER=zuul
2026-01-20 22:36:24.475253 | controller | ZUUL_VOTING=True
2026-01-20 22:36:24.475258 | controller | BUILD_TIMEOUT=1800000
2026-01-20 22:36:24.475263 | controller | SELINUX_USE_CURRENT_RANGE=
2026-01-20 22:36:24.475268 | controller | SHLVL=1
2026-01-20 22:36:24.475274 | controller | ZUUL_PATCHSET=3b80a23c9439dd2e7554486894e6cc29bcabd667
2026-01-20 22:36:24.475279 | controller | XDG_SESSION_ID=1
2026-01-20 22:36:24.475284 | controller | ZUUL_BRANCH=main
2026-01-20 22:36:24.475289 | controller | XDG_RUNTIME_DIR=/run/user/1000
2026-01-20 22:36:24.475295 | controller | SSH_CLIENT=192.168.26.12 42684 22
2026-01-20 22:36:24.475301 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2026-01-20 22:36:24.475307 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2026-01-20 22:36:24.475312 | controller | which_declare=declare -f
2026-01-20 22:36:24.475318 | 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-01-20 22:36:24.475324 | controller | SELINUX_LEVEL_REQUESTED=
2026-01-20 22:36:24.475329 | controller | ZUUL_CHANGE=3451
2026-01-20 22:36:24.475334 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2026-01-20 22:36:24.475339 | controller | ZUUL_UUID=77738fc4868e49afac75e1b1c886952e
2026-01-20 22:36:24.475344 | controller | BASH_FUNC_which%%=() {  ( alias;
2026-01-20 22:36:24.475350 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2026-01-20 22:36:24.475355 | controller | }
2026-01-20 22:36:24.697844 | controller | ok: Runtime: 0:00:00.007141
2026-01-20 22:36:24.704179 | 
2026-01-20 22:36:24.704274 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2026-01-20 22:36:24.733768 | controller | skipping: Conditional result was False
2026-01-20 22:36:24.773643 | 
2026-01-20 22:36:24.773741 | TASK [Symlink /home/zuul-worker/workspace]
2026-01-20 22:36:25.305233 | controller | skipping: Conditional result was False
2026-01-20 22:36:25.315847 | 
2026-01-20 22:36:25.315938 | TASK [Ensure legacy workspace directory]
2026-01-20 22:36:25.615628 | controller | changed
2026-01-20 22:36:25.640907 | 
2026-01-20 22:36:25.641008 | PLAY RECAP
2026-01-20 22:36:25.641077 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2026-01-20 22:36:25.641104 | 
2026-01-20 22:36:25.838719 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2026-01-20 22:36:25.839482 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-01-20 22:36:26.560887 | 
2026-01-20 22:36:26.560983 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2026-01-20 22:36:26.583217 | 
2026-01-20 22:36:26.583347 | TASK [Create zuul-output directory]
2026-01-20 22:36:27.070939 | controller | changed
2026-01-20 22:36:27.076375 | 
2026-01-20 22:36:27.076469 | TASK [Slurp Zuul inventory test]
2026-01-20 22:36:27.702872 | controller -> localhost | ok
2026-01-20 22:36:27.709408 | 
2026-01-20 22:36:27.709493 | TASK [Save zuul inventory]
2026-01-20 22:36:29.298974 | controller | changed
2026-01-20 22:36:29.303897 | 
2026-01-20 22:36:29.303976 | TASK [Save zuul vars without the change_message]
2026-01-20 22:36:30.670869 | controller | changed
2026-01-20 22:36:30.718129 | 
2026-01-20 22:36:30.718209 | PLAY RECAP
2026-01-20 22:36:30.718258 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-20 22:36:30.718283 | 
2026-01-20 22:36:30.877609 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2026-01-20 22:36:30.878357 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-01-20 22:36:31.581823 | 
2026-01-20 22:36:31.581934 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2026-01-20 22:36:31.604157 | 
2026-01-20 22:36:31.604236 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2026-01-20 22:36:31.643822 | controller | ok
2026-01-20 22:36:31.671374 | 
2026-01-20 22:36:31.671469 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2026-01-20 22:36:31.735926 | controller | skipping: Conditional result was False
2026-01-20 22:36:31.741584 | 
2026-01-20 22:36:31.741663 | TASK [mirror-info-fork : Create /etc/ci]
2026-01-20 22:36:32.227176 | controller | ok
2026-01-20 22:36:32.234259 | 
2026-01-20 22:36:32.234349 | TASK [mirror-info-fork : Install ci_mirror script]
2026-01-20 22:36:33.510728 | controller | ok
2026-01-20 22:36:33.524016 | 
2026-01-20 22:36:33.524117 | TASK [Prepare workspace]
2026-01-20 22:36:33.552919 | controller | ok
2026-01-20 22:36:33.571496 | 
2026-01-20 22:36:33.571567 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-20 22:36:34.032566 | controller | ok
2026-01-20 22:36:34.043882 | 
2026-01-20 22:36:34.043968 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-20 22:36:37.695593 | controller | Output suppressed because no_log was given
2026-01-20 22:36:37.712383 | 
2026-01-20 22:36:37.712491 | LOOP [Create zuul-output directory]
2026-01-20 22:36:37.978889 | controller | changed: "/home/zuul/ci-framework-data/logs"
2026-01-20 22:36:38.220679 | controller | ok: "/home/zuul/zuul-output/logs"
2026-01-20 22:36:38.232510 | 
2026-01-20 22:36:38.232615 | TASK [Install required packages]
2026-01-20 22:36:56.640434 | controller | ok: Nothing to do
2026-01-20 22:36:56.651709 | 
2026-01-20 22:36:56.651779 | TASK [Install venv]
2026-01-20 22:37:56.121428 | controller | changed
2026-01-20 22:37:56.167524 | 
2026-01-20 22:37:56.167645 | PLAY RECAP
2026-01-20 22:37:56.167693 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2026-01-20 22:37:56.167717 | 
2026-01-20 22:37:56.243182 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2026-01-20 22:37:56.243975 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-01-20 22:37:56.776447 | 
2026-01-20 22:37:56.776550 | PLAY [Run ci/playbooks/molecule-test.yml]
2026-01-20 22:37:56.797103 | 
2026-01-20 22:37:56.797197 | TASK [Gather required facts]
2026-01-20 22:37:57.343100 | controller | ok
2026-01-20 22:37:57.348397 | 
2026-01-20 22:37:57.348479 | TASK [Load environment var if instructed to]
2026-01-20 22:37:57.372492 | controller | skipping: Conditional result was False
2026-01-20 22:37:57.378033 | 
2026-01-20 22:37:57.378155 | TASK [Ensure group_vars dir exists]
2026-01-20 22:37:57.751389 | controller | ok
2026-01-20 22:37:57.756500 | 
2026-01-20 22:37:57.756564 | TASK [Print related variables]
2026-01-20 22:37:57.784103 | controller | ok:
2026-01-20 22:37:57.784219 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2026-01-20 22:37:57.784249 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/sushy_emulator
2026-01-20 22:37:57.789103 | 
2026-01-20 22:37:57.789193 | TASK [Run molecule]
2026-01-20 22:37:58.781991 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2026-01-20 22:37:58.854053 | controller | INFO     Performing prerun with role_name_check=0...
2026-01-20 22:38:15.304718 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.305146 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.305583 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.306042 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.306514 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+be68611a was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0+be68611a (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.306975 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.307418 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.307866 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.308292 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.308740 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.309169 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.309643 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.310080 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.310542 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.310999 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2026-01-20 22:38:15.320144 | controller | INFO     Running default > prepare
2026-01-20 22:38:15.980365 | controller |
2026-01-20 22:38:15.980468 | controller | PLAY [Prepare] *****************************************************************
2026-01-20 22:38:15.980483 | controller |
2026-01-20 22:38:15.980580 | controller | TASK [Gathering Facts] *********************************************************
2026-01-20 22:38:15.980689 | controller | Tuesday 20 January 2026  22:38:15 +0000 (0:00:00.013)       0:00:00.013 *******
2026-01-20 22:38:16.832638 | controller | ok: [instance]
2026-01-20 22:38:16.832735 | controller |
2026-01-20 22:38:16.832852 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2026-01-20 22:38:16.832964 | controller | Tuesday 20 January 2026  22:38:16 +0000 (0:00:00.852)       0:00:00.866 *******
2026-01-20 22:38:16.850211 | controller | skipping: [instance]
2026-01-20 22:38:16.850294 | controller |
2026-01-20 22:38:16.850424 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2026-01-20 22:38:16.850577 | controller | Tuesday 20 January 2026  22:38:16 +0000 (0:00:00.017)       0:00:00.884 *******
2026-01-20 22:38:16.891500 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2026-01-20 22:38:16.891611 | controller |
2026-01-20 22:38:16.891751 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2026-01-20 22:38:16.891864 | controller | Tuesday 20 January 2026  22:38:16 +0000 (0:00:00.041)       0:00:00.925 *******
2026-01-20 22:38:17.174813 | controller | ok: [instance]
2026-01-20 22:38:17.174865 | controller |
2026-01-20 22:38:17.174978 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2026-01-20 22:38:17.175082 | controller | Tuesday 20 January 2026  22:38:17 +0000 (0:00:00.283)       0:00:01.208 *******
2026-01-20 22:38:17.480937 | controller | ok: [instance]
2026-01-20 22:38:17.481006 | controller |
2026-01-20 22:38:17.481112 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2026-01-20 22:38:17.481223 | controller | Tuesday 20 January 2026  22:38:17 +0000 (0:00:00.306)       0:00:01.514 *******
2026-01-20 22:38:18.168640 | controller | ok: [instance] => (item=ubi-9-appstream)
2026-01-20 22:38:18.168734 | controller | ok: [instance] => (item=ubi-9-baseos)
2026-01-20 22:38:18.168869 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2026-01-20 22:38:18.168968 | controller |
2026-01-20 22:38:18.169073 | controller | TASK [Deploy repo-setup] *******************************************************
2026-01-20 22:38:18.169161 | controller | Tuesday 20 January 2026  22:38:18 +0000 (0:00:00.687)       0:00:02.202 *******
2026-01-20 22:38:18.228832 | controller |
2026-01-20 22:38:18.228943 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2026-01-20 22:38:18.229069 | controller | Tuesday 20 January 2026  22:38:18 +0000 (0:00:00.060)       0:00:02.262 *******
2026-01-20 22:38:18.749403 | controller | changed: [instance] => (item=tmp)
2026-01-20 22:38:18.749474 | controller | changed: [instance] => (item=artifacts/repositories)
2026-01-20 22:38:18.749620 | controller | changed: [instance] => (item=venv/repo_setup)
2026-01-20 22:38:18.749732 | controller |
2026-01-20 22:38:18.749840 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2026-01-20 22:38:18.749935 | controller | Tuesday 20 January 2026  22:38:18 +0000 (0:00:00.520)       0:00:02.783 *******
2026-01-20 22:38:19.563191 | controller | ok: [instance]
2026-01-20 22:38:19.563254 | controller |
2026-01-20 22:38:19.563488 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2026-01-20 22:38:20.654112 | controller | Tuesday 20 January 2026  22:38:19 +0000 (0:00:00.813)       0:00:03.596 *******
2026-01-20 22:38:20.654145 | controller | changed: [instance]
2026-01-20 22:38:28.625646 | controller |
2026-01-20 22:38:28.625684 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2026-01-20 22:38:28.625693 | controller | Tuesday 20 January 2026  22:38:20 +0000 (0:00:01.090)       0:00:04.687 *******
2026-01-20 22:38:28.625703 | controller | changed: [instance]
2026-01-20 22:38:28.625727 | controller |
2026-01-20 22:38:28.625740 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2026-01-20 22:38:28.625747 | controller | Tuesday 20 January 2026  22:38:28 +0000 (0:00:07.971)       0:00:12.659 *******
2026-01-20 22:38:29.326465 | controller | changed: [instance]
2026-01-20 22:38:29.346688 | controller |
2026-01-20 22:38:29.346712 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2026-01-20 22:38:29.346720 | controller | Tuesday 20 January 2026  22:38:29 +0000 (0:00:00.700)       0:00:13.360 *******
2026-01-20 22:38:29.346730 | controller | skipping: [instance]
2026-01-20 22:38:30.153446 | controller |
2026-01-20 22:38:30.153475 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2026-01-20 22:38:30.153483 | controller | Tuesday 20 January 2026  22:38:29 +0000 (0:00:00.020)       0:00:13.380 *******
2026-01-20 22:38:30.153493 | controller | changed: [instance]
2026-01-20 22:38:30.189684 | controller |
2026-01-20 22:38:30.189731 | controller | TASK [repo_setup : Get component repo] *****************************************
2026-01-20 22:38:30.189741 | controller | Tuesday 20 January 2026  22:38:30 +0000 (0:00:00.806)       0:00:14.186 *******
2026-01-20 22:38:30.189755 | controller | skipping: [instance]
2026-01-20 22:38:30.189795 | controller |
2026-01-20 22:38:30.190150 | controller | TASK [repo_setup : Rename component repo] **************************************
2026-01-20 22:38:30.226307 | controller | Tuesday 20 January 2026  22:38:30 +0000 (0:00:00.036)       0:00:14.223 *******
2026-01-20 22:38:30.226332 | controller | skipping: [instance]
2026-01-20 22:38:30.226356 | controller |
2026-01-20 22:38:30.226365 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2026-01-20 22:38:30.226880 | controller | Tuesday 20 January 2026  22:38:30 +0000 (0:00:00.036)       0:00:14.260 *******
2026-01-20 22:38:30.261643 | controller | skipping: [instance]
2026-01-20 22:38:30.262159 | controller |
2026-01-20 22:38:30.797662 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2026-01-20 22:38:30.797700 | controller | Tuesday 20 January 2026  22:38:30 +0000 (0:00:00.035)       0:00:14.295 *******
2026-01-20 22:38:30.797716 | controller | changed: [instance]
2026-01-20 22:38:31.241455 | controller |
2026-01-20 22:38:31.241489 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2026-01-20 22:38:31.241497 | controller | Tuesday 20 January 2026  22:38:30 +0000 (0:00:00.535)       0:00:14.831 *******
2026-01-20 22:38:31.241507 | controller | changed: [instance]
2026-01-20 22:38:31.271265 | controller |
2026-01-20 22:38:31.271293 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2026-01-20 22:38:31.271303 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.443)       0:00:15.275 *******
2026-01-20 22:38:31.271314 | controller | skipping: [instance]
2026-01-20 22:38:31.300217 | controller |
2026-01-20 22:38:31.300244 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2026-01-20 22:38:31.300253 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.029)       0:00:15.304 *******
2026-01-20 22:38:31.300269 | controller | skipping: [instance]
2026-01-20 22:38:31.329068 | controller |
2026-01-20 22:38:31.329091 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2026-01-20 22:38:31.329101 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.029)       0:00:15.333 *******
2026-01-20 22:38:31.329112 | controller | skipping: [instance]
2026-01-20 22:38:31.367507 | controller |
2026-01-20 22:38:31.367534 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2026-01-20 22:38:31.367542 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.028)       0:00:15.362 *******
2026-01-20 22:38:31.367552 | controller | ok: [instance]
2026-01-20 22:38:31.395691 | controller |
2026-01-20 22:38:31.395726 | controller | TASK [repo_setup : Create download directory] **********************************
2026-01-20 22:38:31.395736 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.038)       0:00:15.401 *******
2026-01-20 22:38:31.395749 | controller | skipping: [instance]
2026-01-20 22:38:31.424529 | controller |
2026-01-20 22:38:31.424548 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2026-01-20 22:38:31.424556 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.027)       0:00:15.429 *******
2026-01-20 22:38:31.424593 | controller | skipping: [instance]
2026-01-20 22:38:31.424717 | controller |
2026-01-20 22:38:31.424857 | controller | TASK [Download the RPM] ********************************************************
2026-01-20 22:38:31.424998 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.029)       0:00:15.458 *******
2026-01-20 22:38:31.453996 | controller | skipping: [instance]
2026-01-20 22:38:31.454129 | controller |
2026-01-20 22:38:31.454306 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2026-01-20 22:38:31.454421 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.029)       0:00:15.487 *******
2026-01-20 22:38:31.507054 | controller | skipping: [instance]
2026-01-20 22:38:31.507144 | controller |
2026-01-20 22:38:31.507284 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2026-01-20 22:38:31.507393 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.052)       0:00:15.540 *******
2026-01-20 22:38:31.533873 | controller | skipping: [instance]
2026-01-20 22:38:31.534006 | controller |
2026-01-20 22:38:31.534133 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2026-01-20 22:38:31.534252 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.026)       0:00:15.567 *******
2026-01-20 22:38:31.562342 | controller | skipping: [instance]
2026-01-20 22:38:31.562500 | controller |
2026-01-20 22:38:31.562682 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2026-01-20 22:38:31.562810 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.028)       0:00:15.596 *******
2026-01-20 22:38:31.588264 | controller | skipping: [instance]
2026-01-20 22:38:31.588387 | controller |
2026-01-20 22:38:31.588557 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2026-01-20 22:38:31.588697 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.025)       0:00:15.622 *******
2026-01-20 22:38:31.774534 | controller | ok: [instance]
2026-01-20 22:38:31.774663 | controller |
2026-01-20 22:38:31.774793 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2026-01-20 22:38:31.774920 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.185)       0:00:15.808 *******
2026-01-20 22:38:31.990352 | controller | changed: [instance]
2026-01-20 22:38:32.219140 | controller |
2026-01-20 22:38:32.219170 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2026-01-20 22:38:32.219178 | controller | Tuesday 20 January 2026  22:38:31 +0000 (0:00:00.215)       0:00:16.023 *******
2026-01-20 22:38:32.219188 | controller | changed: [instance]
2026-01-20 22:38:32.239319 | controller |
2026-01-20 22:38:32.239340 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2026-01-20 22:38:32.239347 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.228)       0:00:16.252 *******
2026-01-20 22:38:32.239356 | controller | skipping: [instance]
2026-01-20 22:38:32.260686 | controller |
2026-01-20 22:38:32.260723 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2026-01-20 22:38:32.260733 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.020)       0:00:16.273 *******
2026-01-20 22:38:32.260746 | controller | skipping: [instance]
2026-01-20 22:38:32.260776 | controller |
2026-01-20 22:38:32.260786 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2026-01-20 22:38:32.260864 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.021)       0:00:16.294 *******
2026-01-20 22:38:32.282498 | controller | skipping: [instance]
2026-01-20 22:38:32.305133 | controller |
2026-01-20 22:38:32.305155 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2026-01-20 22:38:32.305164 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.021)       0:00:16.316 *******
2026-01-20 22:38:32.305179 | controller | skipping: [instance]
2026-01-20 22:38:32.327258 | controller |
2026-01-20 22:38:32.327280 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2026-01-20 22:38:32.327289 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.022)       0:00:16.338 *******
2026-01-20 22:38:32.327300 | controller | skipping: [instance]
2026-01-20 22:38:32.350653 | controller |
2026-01-20 22:38:32.350679 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2026-01-20 22:38:32.350698 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.022)       0:00:16.360 *******
2026-01-20 22:38:32.350709 | controller | skipping: [instance]
2026-01-20 22:38:32.350899 | controller |
2026-01-20 22:38:32.351109 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2026-01-20 22:38:32.351273 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.023)       0:00:16.384 *******
2026-01-20 22:38:32.366354 | controller | skipping: [instance]
2026-01-20 22:38:32.366542 | controller |
2026-01-20 22:38:32.366717 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2026-01-20 22:38:32.366861 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.015)       0:00:16.400 *******
2026-01-20 22:38:32.396988 | controller | skipping: [instance]
2026-01-20 22:38:32.397178 | controller |
2026-01-20 22:38:32.397352 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2026-01-20 22:38:32.397517 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.030)       0:00:16.431 *******
2026-01-20 22:38:32.413268 | controller | skipping: [instance]
2026-01-20 22:38:32.413456 | controller |
2026-01-20 22:38:32.413659 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2026-01-20 22:38:32.413810 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.016)       0:00:16.447 *******
2026-01-20 22:38:32.433088 | controller | skipping: [instance]
2026-01-20 22:38:32.433273 | controller |
2026-01-20 22:38:32.433448 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2026-01-20 22:38:32.433651 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.019)       0:00:16.467 *******
2026-01-20 22:38:32.461968 | controller | skipping: [instance]
2026-01-20 22:38:32.462162 | controller |
2026-01-20 22:38:32.462340 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2026-01-20 22:38:32.462507 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.028)       0:00:16.496 *******
2026-01-20 22:38:32.491405 | controller | skipping: [instance]
2026-01-20 22:38:32.491620 | controller |
2026-01-20 22:38:32.491809 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2026-01-20 22:38:32.491957 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.029)       0:00:16.525 *******
2026-01-20 22:38:32.521272 | controller | skipping: [instance]
2026-01-20 22:38:32.521457 | controller |
2026-01-20 22:38:32.521664 | controller | TASK [test_deps : Install additional packages] *********************************
2026-01-20 22:38:32.521838 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.029)       0:00:16.555 *******
2026-01-20 22:38:32.550278 | controller | skipping: [instance]
2026-01-20 22:38:32.550465 | controller |
2026-01-20 22:38:32.550671 | controller | TASK [test_deps : Install selinux python libs] *********************************
2026-01-20 22:38:32.550845 | controller | Tuesday 20 January 2026  22:38:32 +0000 (0:00:00.028)       0:00:16.584 *******
2026-01-20 22:39:16.370668 | controller | ok: [instance]
2026-01-20 22:39:16.370722 | controller |
2026-01-20 22:39:16.370731 | controller | TASK [test_deps : Install python yaml libs] ************************************
2026-01-20 22:39:16.370739 | controller | Tuesday 20 January 2026  22:39:16 +0000 (0:00:43.819)       0:01:00.404 *******
2026-01-20 22:39:17.642158 | controller | ok: [instance]
2026-01-20 22:39:17.672042 | controller |
2026-01-20 22:39:17.672070 | controller | TASK [test_deps : Install extra packages] **************************************
2026-01-20 22:39:17.672077 | controller | Tuesday 20 January 2026  22:39:17 +0000 (0:00:01.271)       0:01:01.675 *******
2026-01-20 22:39:17.672088 | controller | skipping: [instance]
2026-01-20 22:42:04.929815 | controller |
2026-01-20 22:42:04.929882 | controller | TASK [Ensure CRC is started] ***************************************************
2026-01-20 22:42:04.929894 | controller | Tuesday 20 January 2026  22:39:17 +0000 (0:00:00.029)       0:01:01.705 *******
2026-01-20 22:42:04.929906 | controller | changed: [instance]
2026-01-20 22:42:05.248155 | controller |
2026-01-20 22:42:05.248208 | controller | TASK [Inject crc hostname/IP in hosts] *****************************************
2026-01-20 22:42:05.248218 | controller | Tuesday 20 January 2026  22:42:04 +0000 (0:02:47.257)       0:03:48.962 *******
2026-01-20 22:42:05.248229 | controller | changed: [instance]
2026-01-20 22:42:05.248274 | controller |
2026-01-20 22:42:05.248630 | controller | PLAY RECAP *********************************************************************
2026-01-20 22:42:05.248661 | controller | instance                   : ok=21   changed=11   unreachable=0    failed=0    skipped=30   rescued=0    ignored=0
2026-01-20 22:42:05.248668 | controller |
2026-01-20 22:42:05.248675 | controller | Tuesday 20 January 2026  22:42:05 +0000 (0:00:00.318)       0:03:49.281 *******
2026-01-20 22:42:05.249829 | controller | ===============================================================================
2026-01-20 22:42:05.250066 | controller | Ensure CRC is started ------------------------------------------------- 167.26s
2026-01-20 22:42:05.250081 | controller | test_deps : Install selinux python libs -------------------------------- 43.82s
2026-01-20 22:42:05.250088 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.97s
2026-01-20 22:42:05.250093 | controller | test_deps : Install python yaml libs ------------------------------------ 1.27s
2026-01-20 22:42:05.250098 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.09s
2026-01-20 22:42:05.250104 | controller | Gathering Facts --------------------------------------------------------- 0.85s
2026-01-20 22:42:05.250109 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.81s
2026-01-20 22:42:05.250114 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.81s
2026-01-20 22:42:05.250120 | controller | repo_setup : Install repo-setup package --------------------------------- 0.70s
2026-01-20 22:42:05.250125 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.69s
2026-01-20 22:42:05.250130 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.54s
2026-01-20 22:42:05.250138 | controller | repo_setup : Ensure directories are present ----------------------------- 0.52s
2026-01-20 22:42:05.250161 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.44s
2026-01-20 22:42:05.250168 | controller | Inject crc hostname/IP in hosts ----------------------------------------- 0.32s
2026-01-20 22:42:05.250761 | controller | test_deps : Disable ubi host subscription-manager integration ----------- 0.31s
2026-01-20 22:42:05.318039 | controller | test_deps : Detect mirrors file ----------------------------------------- 0.28s
2026-01-20 22:42:05.318072 | controller | repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist) --- 0.23s
2026-01-20 22:42:05.318080 | controller | repo_setup : Use RDO proxy mirrors -------------------------------------- 0.22s
2026-01-20 22:42:05.318087 | controller | repo_setup : Check for /etc/ci/mirror_info.sh --------------------------- 0.19s
2026-01-20 22:42:05.318093 | controller | Deploy repo-setup ------------------------------------------------------- 0.06s
2026-01-20 22:42:05.318103 | controller | INFO     Running default > converge
2026-01-20 22:42:05.777260 | controller |
2026-01-20 22:42:05.777499 | controller | PLAY [Converge] ****************************************************************
2026-01-20 22:42:05.777660 | controller |
2026-01-20 22:42:05.777802 | controller | TASK [Gathering Facts] *********************************************************
2026-01-20 22:42:05.777937 | controller | Tuesday 20 January 2026  22:42:05 +0000 (0:00:00.016)       0:00:00.016 *******
2026-01-20 22:42:06.677665 | controller | ok: [instance]
2026-01-20 22:42:06.695302 | controller |
2026-01-20 22:42:06.695345 | controller | TASK [Load networking_definition] **********************************************
2026-01-20 22:42:06.695355 | controller | Tuesday 20 January 2026  22:42:06 +0000 (0:00:00.900)       0:00:00.917 *******
2026-01-20 22:42:06.695367 | controller | ok: [instance]
2026-01-20 22:42:06.718688 | controller |
2026-01-20 22:42:06.718728 | controller | TASK [Check if new ssh keypair exists] *****************************************
2026-01-20 22:42:06.718737 | controller | Tuesday 20 January 2026  22:42:06 +0000 (0:00:00.018)       0:00:00.935 *******
2026-01-20 22:42:06.718748 | controller |
2026-01-20 22:42:07.025061 | controller | TASK [recognize_ssh_keypair : Check if id_ed25519 key exists] ******************
2026-01-20 22:42:07.025102 | controller | Tuesday 20 January 2026  22:42:06 +0000 (0:00:00.023)       0:00:00.958 *******
2026-01-20 22:42:07.025116 | controller | ok: [instance]
2026-01-20 22:42:07.025143 | controller |
2026-01-20 22:42:07.025163 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair exists] ******************
2026-01-20 22:42:07.025171 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.306)       0:00:01.265 *******
2026-01-20 22:42:07.046482 | controller | ok: [instance]
2026-01-20 22:42:07.046547 | controller |
2026-01-20 22:42:07.046591 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair does not exists] *********
2026-01-20 22:42:07.046682 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.021)       0:00:01.286 *******
2026-01-20 22:42:07.069980 | controller | skipping: [instance]
2026-01-20 22:42:07.070130 | controller |
2026-01-20 22:42:07.070157 | controller | TASK [Add the crc host dynamically] ********************************************
2026-01-20 22:42:07.070171 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.023)       0:00:01.310 *******
2026-01-20 22:42:07.092705 | controller | changed: [instance]
2026-01-20 22:42:07.092759 | controller |
2026-01-20 22:42:07.092771 | controller | TASK [Add ansible_host entry to "controller-0"] ********************************
2026-01-20 22:42:07.092894 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.022)       0:00:01.333 *******
2026-01-20 22:42:07.120160 | controller | changed: [instance]
2026-01-20 22:42:07.120216 | controller |
2026-01-20 22:42:07.120225 | controller | TASK [Add host key to controller-0] ********************************************
2026-01-20 22:42:07.120235 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.027)       0:00:01.360 *******
2026-01-20 22:42:07.463679 | controller | changed: [instance]
2026-01-20 22:42:07.463897 | controller |
2026-01-20 22:42:07.463916 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2026-01-20 22:42:07.776548 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.343)       0:00:01.703 *******
2026-01-20 22:42:07.776613 | controller | ok: [instance]
2026-01-20 22:42:07.972056 | controller |
2026-01-20 22:42:07.972091 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2026-01-20 22:42:07.972100 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.312)       0:00:02.016 *******
2026-01-20 22:42:07.972110 | controller | changed: [instance]
2026-01-20 22:42:08.167405 | controller |
2026-01-20 22:42:08.167447 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2026-01-20 22:42:08.167458 | controller | Tuesday 20 January 2026  22:42:07 +0000 (0:00:00.195)       0:00:02.211 *******
2026-01-20 22:42:08.167471 | controller | ok: [instance]
2026-01-20 22:42:08.167502 | controller |
2026-01-20 22:42:08.167693 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2026-01-20 22:42:08.167736 | controller | Tuesday 20 January 2026  22:42:08 +0000 (0:00:00.195)       0:00:02.407 *******
2026-01-20 22:42:08.197716 | controller | skipping: [instance]
2026-01-20 22:42:08.197945 | controller |
2026-01-20 22:42:08.197970 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2026-01-20 22:42:08.217080 | controller | Tuesday 20 January 2026  22:42:08 +0000 (0:00:00.030)       0:00:02.437 *******
2026-01-20 22:42:08.217108 | controller | skipping: [instance]
2026-01-20 22:42:08.238048 | controller |
2026-01-20 22:42:08.238072 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2026-01-20 22:42:08.238082 | controller | Tuesday 20 January 2026  22:42:08 +0000 (0:00:00.019)       0:00:02.457 *******
2026-01-20 22:42:08.238092 | controller | ok: [instance]
2026-01-20 22:42:08.238256 | controller |
2026-01-20 22:42:08.238273 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2026-01-20 22:42:08.265986 | controller | Tuesday 20 January 2026  22:42:08 +0000 (0:00:00.021)       0:00:02.478 *******
2026-01-20 22:42:08.266008 | controller | skipping: [instance]
2026-01-20 22:42:08.266037 | controller |
2026-01-20 22:42:08.266366 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2026-01-20 22:42:16.936797 | controller | Tuesday 20 January 2026  22:42:08 +0000 (0:00:00.027)       0:00:02.506 *******
2026-01-20 22:42:16.936847 | controller | changed: [instance]
2026-01-20 22:42:16.936858 | controller |
2026-01-20 22:42:16.937035 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2026-01-20 22:42:17.147179 | controller | Tuesday 20 January 2026  22:42:16 +0000 (0:00:08.666)       0:00:11.173 *******
2026-01-20 22:42:17.147233 | controller | changed: [instance]
2026-01-20 22:42:17.637832 | controller |
2026-01-20 22:42:17.637870 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2026-01-20 22:42:17.637879 | controller | Tuesday 20 January 2026  22:42:17 +0000 (0:00:00.213)       0:00:11.387 *******
2026-01-20 22:42:17.637903 | controller | changed: [instance]
2026-01-20 22:42:17.638027 | controller |
2026-01-20 22:42:17.638040 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2026-01-20 22:42:17.638584 | controller | Tuesday 20 January 2026  22:42:17 +0000 (0:00:00.490)       0:00:11.878 *******
2026-01-20 22:42:18.213254 | controller | changed: [instance]
2026-01-20 22:42:18.213322 | controller |
2026-01-20 22:42:18.213427 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2026-01-20 22:42:18.213528 | controller | Tuesday 20 January 2026  22:42:18 +0000 (0:00:00.575)       0:00:12.453 *******
2026-01-20 22:42:18.411041 | controller | ok: [instance]
2026-01-20 22:42:18.411083 | controller |
2026-01-20 22:42:18.411192 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2026-01-20 22:42:18.411356 | controller | Tuesday 20 January 2026  22:42:18 +0000 (0:00:00.197)       0:00:12.651 *******
2026-01-20 22:42:19.092100 | controller | ok: [instance]
2026-01-20 22:42:20.092636 | controller |
2026-01-20 22:42:20.092672 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2026-01-20 22:42:20.092680 | controller | Tuesday 20 January 2026  22:42:19 +0000 (0:00:00.679)       0:00:13.330 *******
2026-01-20 22:42:20.092691 | controller | changed: [instance]
2026-01-20 22:42:20.092829 | controller |
2026-01-20 22:42:20.092843 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2026-01-20 22:42:20.178638 | controller | Tuesday 20 January 2026  22:42:20 +0000 (0:00:01.001)       0:00:14.331 *******
2026-01-20 22:42:20.178697 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2026-01-20 22:42:20.514358 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2026-01-20 22:42:20.514396 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2026-01-20 22:42:20.514404 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2026-01-20 22:42:20.514410 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2026-01-20 22:42:20.514415 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2026-01-20 22:42:20.514421 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2026-01-20 22:42:20.514426 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2026-01-20 22:42:20.514432 | controller |
2026-01-20 22:42:20.514437 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2026-01-20 22:42:20.514444 | controller | Tuesday 20 January 2026  22:42:20 +0000 (0:00:00.084)       0:00:14.416 *******
2026-01-20 22:42:20.514456 | controller | ok: [instance]
2026-01-20 22:42:20.514500 | controller |
2026-01-20 22:42:20.514509 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2026-01-20 22:42:20.514594 | controller | Tuesday 20 January 2026  22:42:20 +0000 (0:00:00.337)       0:00:14.754 *******
2026-01-20 22:42:20.845709 | controller | ok: [instance]
2026-01-20 22:42:20.846000 | controller |
2026-01-20 22:42:21.175604 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2026-01-20 22:42:21.175640 | controller | Tuesday 20 January 2026  22:42:20 +0000 (0:00:00.331)       0:00:15.085 *******
2026-01-20 22:42:21.175655 | controller | ok: [instance]
2026-01-20 22:42:21.505642 | controller |
2026-01-20 22:42:21.505700 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2026-01-20 22:42:21.505720 | controller | Tuesday 20 January 2026  22:42:21 +0000 (0:00:00.329)       0:00:15.415 *******
2026-01-20 22:42:21.505736 | controller | ok: [instance]
2026-01-20 22:42:21.505779 | controller |
2026-01-20 22:42:21.505980 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2026-01-20 22:42:21.840350 | controller | Tuesday 20 January 2026  22:42:21 +0000 (0:00:00.330)       0:00:15.745 *******
2026-01-20 22:42:21.840397 | controller | ok: [instance]
2026-01-20 22:42:21.840419 | controller |
2026-01-20 22:42:21.840524 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2026-01-20 22:42:21.840669 | controller | Tuesday 20 January 2026  22:42:21 +0000 (0:00:00.334)       0:00:16.080 *******
2026-01-20 22:42:22.169167 | controller | ok: [instance]
2026-01-20 22:42:22.169231 | controller |
2026-01-20 22:42:22.169333 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2026-01-20 22:42:22.169428 | controller | Tuesday 20 January 2026  22:42:22 +0000 (0:00:00.328)       0:00:16.409 *******
2026-01-20 22:42:22.501263 | controller | ok: [instance]
2026-01-20 22:42:22.501337 | controller |
2026-01-20 22:42:22.501447 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2026-01-20 22:42:22.501553 | controller | Tuesday 20 January 2026  22:42:22 +0000 (0:00:00.332)       0:00:16.741 *******
2026-01-20 22:42:23.838714 | controller | ok: [instance]
2026-01-20 22:42:24.209734 | controller |
2026-01-20 22:42:24.209781 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2026-01-20 22:42:24.209789 | controller | Tuesday 20 January 2026  22:42:23 +0000 (0:00:01.337)       0:00:18.078 *******
2026-01-20 22:42:24.209801 | controller | ok: [instance]
2026-01-20 22:42:24.210005 | controller |
2026-01-20 22:42:24.210028 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2026-01-20 22:42:24.608610 | controller | Tuesday 20 January 2026  22:42:24 +0000 (0:00:00.371)       0:00:18.449 *******
2026-01-20 22:42:24.608660 | controller | ok: [instance]
2026-01-20 22:42:24.968698 | controller |
2026-01-20 22:42:24.968736 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2026-01-20 22:42:24.968745 | controller | Tuesday 20 January 2026  22:42:24 +0000 (0:00:00.397)       0:00:18.847 *******
2026-01-20 22:42:24.968757 | controller | ok: [instance]
2026-01-20 22:42:24.968904 | controller |
2026-01-20 22:42:24.968914 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2026-01-20 22:42:24.968922 | controller | Tuesday 20 January 2026  22:42:24 +0000 (0:00:00.360)       0:00:19.208 *******
2026-01-20 22:42:25.326512 | controller | ok: [instance]
2026-01-20 22:42:25.326625 | controller |
2026-01-20 22:42:25.326704 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2026-01-20 22:42:25.326805 | controller | Tuesday 20 January 2026  22:42:25 +0000 (0:00:00.358)       0:00:19.566 *******
2026-01-20 22:42:25.670848 | controller | ok: [instance]
2026-01-20 22:42:26.027084 | controller |
2026-01-20 22:42:26.027138 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2026-01-20 22:42:26.027152 | controller | Tuesday 20 January 2026  22:42:25 +0000 (0:00:00.343)       0:00:19.910 *******
2026-01-20 22:42:26.027167 | controller | ok: [instance]
2026-01-20 22:42:26.028650 | controller |
2026-01-20 22:42:26.028722 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2026-01-20 22:42:26.429669 | controller | Tuesday 20 January 2026  22:42:26 +0000 (0:00:00.356)       0:00:20.266 *******
2026-01-20 22:42:26.429718 | controller | ok: [instance]
2026-01-20 22:42:26.868554 | controller |
2026-01-20 22:42:26.868612 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2026-01-20 22:42:26.868624 | controller | Tuesday 20 January 2026  22:42:26 +0000 (0:00:00.402)       0:00:20.669 *******
2026-01-20 22:42:26.868637 | controller | ok: [instance]
2026-01-20 22:42:27.259872 | controller |
2026-01-20 22:42:27.259934 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2026-01-20 22:42:27.259944 | controller | Tuesday 20 January 2026  22:42:26 +0000 (0:00:00.438)       0:00:21.108 *******
2026-01-20 22:42:27.259957 | controller | ok: [instance]
2026-01-20 22:42:27.687673 | controller |
2026-01-20 22:42:27.687718 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2026-01-20 22:42:27.687736 | controller | Tuesday 20 January 2026  22:42:27 +0000 (0:00:00.391)       0:00:21.499 *******
2026-01-20 22:42:27.687752 | controller | ok: [instance]
2026-01-20 22:42:29.086751 | controller |
2026-01-20 22:42:29.086782 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2026-01-20 22:42:29.086790 | controller | Tuesday 20 January 2026  22:42:27 +0000 (0:00:00.427)       0:00:21.926 *******
2026-01-20 22:42:29.086804 | controller | ok: [instance]
2026-01-20 22:42:29.086842 | controller |
2026-01-20 22:42:29.086986 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2026-01-20 22:42:29.087114 | controller | Tuesday 20 January 2026  22:42:29 +0000 (0:00:01.400)       0:00:23.326 *******
2026-01-20 22:42:29.449361 | controller | ok: [instance]
2026-01-20 22:42:29.449461 | controller |
2026-01-20 22:42:29.449607 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2026-01-20 22:42:29.449749 | controller | Tuesday 20 January 2026  22:42:29 +0000 (0:00:00.362)       0:00:23.689 *******
2026-01-20 22:42:29.817718 | controller | ok: [instance]
2026-01-20 22:42:29.817821 | controller |
2026-01-20 22:42:29.817960 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2026-01-20 22:42:29.818089 | controller | Tuesday 20 January 2026  22:42:29 +0000 (0:00:00.368)       0:00:24.058 *******
2026-01-20 22:42:30.184516 | controller | ok: [instance]
2026-01-20 22:42:30.184669 | controller |
2026-01-20 22:42:30.184823 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2026-01-20 22:42:30.184962 | controller | Tuesday 20 January 2026  22:42:30 +0000 (0:00:00.366)       0:00:24.424 *******
2026-01-20 22:42:30.536500 | controller | ok: [instance]
2026-01-20 22:42:30.536555 | controller |
2026-01-20 22:42:30.536739 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2026-01-20 22:42:30.536859 | controller | Tuesday 20 January 2026  22:42:30 +0000 (0:00:00.352)       0:00:24.777 *******
2026-01-20 22:42:30.886524 | controller | ok: [instance]
2026-01-20 22:42:30.908400 | controller |
2026-01-20 22:42:30.908421 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2026-01-20 22:42:30.908429 | controller | Tuesday 20 January 2026  22:42:30 +0000 (0:00:00.346)       0:00:25.123 *******
2026-01-20 22:42:30.908438 | controller | skipping: [instance]
2026-01-20 22:42:31.209457 | controller |
2026-01-20 22:42:31.209484 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2026-01-20 22:42:31.209492 | controller | Tuesday 20 January 2026  22:42:30 +0000 (0:00:00.025)       0:00:25.148 *******
2026-01-20 22:42:31.209501 | controller | ok: [instance]
2026-01-20 22:42:31.632703 | controller |
2026-01-20 22:42:31.632742 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2026-01-20 22:42:31.632751 | controller | Tuesday 20 January 2026  22:42:31 +0000 (0:00:00.300)       0:00:25.449 *******
2026-01-20 22:42:31.632765 | controller | ok: [instance]
2026-01-20 22:42:31.991334 | controller |
2026-01-20 22:42:31.991359 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2026-01-20 22:42:31.991367 | controller | Tuesday 20 January 2026  22:42:31 +0000 (0:00:00.418)       0:00:25.868 *******
2026-01-20 22:42:31.991376 | controller | changed: [instance]
2026-01-20 22:42:32.344146 | controller |
2026-01-20 22:42:32.344186 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2026-01-20 22:42:32.344197 | controller | Tuesday 20 January 2026  22:42:31 +0000 (0:00:00.362)       0:00:26.230 *******
2026-01-20 22:42:32.344209 | controller | [WARNING]: Reset is not implemented for this connection
2026-01-20 22:42:32.357355 | controller | changed: [instance]
2026-01-20 22:42:32.439467 | controller |
2026-01-20 22:42:32.439514 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2026-01-20 22:42:32.439523 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.346)       0:00:26.577 *******
2026-01-20 22:42:32.439529 | controller |
2026-01-20 22:42:32.439535 | controller | TASK [Create virtual baremetal VMs] ********************************************
2026-01-20 22:42:32.439540 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.019)       0:00:26.596 *******
2026-01-20 22:42:32.439550 | controller |
2026-01-20 22:42:32.475621 | controller | TASK [libvirt_manager : Import layout generator if needed] *********************
2026-01-20 22:42:32.475657 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.082)       0:00:26.679 *******
2026-01-20 22:42:32.475673 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_layout.yml for instance
2026-01-20 22:42:32.520498 | controller |
2026-01-20 22:42:32.520521 | controller | TASK [libvirt_manager : Chose right parameter for layout definition] ***********
2026-01-20 22:42:32.520536 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.036)       0:00:26.715 *******
2026-01-20 22:42:32.520548 | controller | ok: [instance]
2026-01-20 22:42:32.606823 | controller |
2026-01-20 22:42:32.606846 | controller | TASK [libvirt_manager : Patch the layout if needed] ****************************
2026-01-20 22:42:32.606859 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.044)       0:00:26.759 *******
2026-01-20 22:42:32.606868 | controller | skipping: [instance]
2026-01-20 22:42:33.136991 | controller |
2026-01-20 22:42:33.137043 | controller | TASK [libvirt_manager : Enable forwarding in the libvirt zone] *****************
2026-01-20 22:42:33.137052 | controller | Tuesday 20 January 2026  22:42:32 +0000 (0:00:00.086)       0:00:26.846 *******
2026-01-20 22:42:33.137064 | controller | changed: [instance]
2026-01-20 22:42:33.766065 | controller |
2026-01-20 22:42:33.766104 | controller | TASK [libvirt_manager : Enable masquerading for public traffic] ****************
2026-01-20 22:42:33.766112 | controller | Tuesday 20 January 2026  22:42:33 +0000 (0:00:00.529)       0:00:27.376 *******
2026-01-20 22:42:33.766123 | controller | changed: [instance]
2026-01-20 22:42:34.761186 | controller |
2026-01-20 22:42:34.761221 | controller | TASK [libvirt_manager : Ensure firewalld is restarts] **************************
2026-01-20 22:42:34.761230 | controller | Tuesday 20 January 2026  22:42:33 +0000 (0:00:00.616)       0:00:27.993 *******
2026-01-20 22:42:34.761236 | controller |
2026-01-20 22:42:34.761241 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2026-01-20 22:42:34.761251 | controller | Tuesday 20 January 2026  22:42:33 +0000 (0:00:00.012)       0:00:28.005 *******
2026-01-20 22:42:34.761261 | controller | changed: [instance]
2026-01-20 22:42:34.796930 | controller |
2026-01-20 22:42:34.796960 | controller | TASK [Deploy virtualbmc] *******************************************************
2026-01-20 22:42:34.796973 | controller | Tuesday 20 January 2026  22:42:34 +0000 (0:00:00.990)       0:00:28.996 *******
2026-01-20 22:42:34.796984 | controller | skipping: [instance]
2026-01-20 22:42:34.833164 | controller |
2026-01-20 22:42:34.833192 | controller | TASK [libvirt_manager : Let the project know we have vbmc available] ***********
2026-01-20 22:42:34.833200 | controller | Tuesday 20 January 2026  22:42:34 +0000 (0:00:00.040)       0:00:29.036 *******
2026-01-20 22:42:34.833209 | controller | skipping: [instance]
2026-01-20 22:42:35.567795 | controller |
2026-01-20 22:42:35.567829 | controller | TASK [libvirt_manager : Create needed workload directory] **********************
2026-01-20 22:42:35.567837 | controller | Tuesday 20 January 2026  22:42:34 +0000 (0:00:00.036)       0:00:29.073 *******
2026-01-20 22:42:35.567848 | controller | changed: [instance] => (item=workload)
2026-01-20 22:42:36.093860 | controller | changed: [instance] => (item=reproducer-inventory)
2026-01-20 22:42:36.093895 | controller | changed: [instance] => (item=volumes)
2026-01-20 22:42:36.093903 | controller |
2026-01-20 22:42:36.093913 | controller | TASK [libvirt_manager : Allow QEMU on workload directory] **********************
2026-01-20 22:42:36.093926 | controller | Tuesday 20 January 2026  22:42:35 +0000 (0:00:00.731)       0:00:29.804 *******
2026-01-20 22:42:36.093936 | controller | changed: [instance] => (item=workload)
2026-01-20 22:42:36.202253 | controller | changed: [instance] => (item=volumes)
2026-01-20 22:42:36.202304 | controller |
2026-01-20 22:42:36.202312 | controller | TASK [libvirt_manager : Generate networking data] ******************************
2026-01-20 22:42:36.202319 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.529)       0:00:30.333 *******
2026-01-20 22:42:36.202335 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_networking_data.yml for instance
2026-01-20 22:42:36.225472 | controller |
2026-01-20 22:42:36.225512 | controller | TASK [libvirt_manager : Ensure fact is existing, and empty] ********************
2026-01-20 22:42:36.225529 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.108)       0:00:30.441 *******
2026-01-20 22:42:36.225548 | controller | ok: [instance]
2026-01-20 22:42:36.442019 | controller |
2026-01-20 22:42:36.442069 | controller | TASK [libvirt_manager : Check if we get an existing interfaces-info.yml] *******
2026-01-20 22:42:36.442079 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.023)       0:00:30.465 *******
2026-01-20 22:42:36.442095 | controller | ok: [instance]
2026-01-20 22:42:36.477956 | controller |
2026-01-20 22:42:36.477991 | controller | TASK [libvirt_manager : Load file if exists] ***********************************
2026-01-20 22:42:36.478002 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.216)       0:00:30.681 *******
2026-01-20 22:42:36.478014 | controller | skipping: [instance]
2026-01-20 22:42:36.511123 | controller |
2026-01-20 22:42:36.511149 | controller | TASK [libvirt_manager : Update fact with existing content] *********************
2026-01-20 22:42:36.511158 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.036)       0:00:30.717 *******
2026-01-20 22:42:36.511175 | controller | skipping: [instance]
2026-01-20 22:42:36.570257 | controller |
2026-01-20 22:42:36.570307 | controller | TASK [libvirt_manager : Generate VM list] **************************************
2026-01-20 22:42:36.570317 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.033)       0:00:30.750 *******
2026-01-20 22:42:36.570329 | controller | ok: [instance]
2026-01-20 22:42:36.688194 | controller |
2026-01-20 22:42:36.688246 | controller | TASK [libvirt_manager : Generate/update mapping all nodes] *********************
2026-01-20 22:42:36.688255 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.058)       0:00:30.809 *******
2026-01-20 22:42:36.688267 | controller | ok: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2026-01-20 22:42:36.728379 | controller | ok: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2026-01-20 22:42:36.728430 | controller |
2026-01-20 22:42:36.728446 | controller | TASK [libvirt_manager : Append baremetal nodes if needed] **********************
2026-01-20 22:42:36.728455 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.117)       0:00:30.927 *******
2026-01-20 22:42:36.728466 | controller | skipping: [instance]
2026-01-20 22:42:37.132858 | controller |
2026-01-20 22:42:37.132892 | controller | TASK [libvirt_manager : Dump MAC mapping] **************************************
2026-01-20 22:42:37.132901 | controller | Tuesday 20 January 2026  22:42:36 +0000 (0:00:00.040)       0:00:30.967 *******
2026-01-20 22:42:37.132911 | controller | changed: [instance]
2026-01-20 22:42:37.234668 | controller |
2026-01-20 22:42:37.234692 | controller | TASK [libvirt_manager : Inject all VMs in the inventory] ***********************
2026-01-20 22:42:37.234701 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.404)       0:00:31.372 *******
2026-01-20 22:42:37.234712 | controller | changed: [instance] => (item=Adding compute-0 to computes)
2026-01-20 22:42:37.261169 | controller | changed: [instance] => (item=Adding compute-1 to computes)
2026-01-20 22:42:37.261188 | controller |
2026-01-20 22:42:37.261196 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2026-01-20 22:42:37.261201 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.101)       0:00:31.474 *******
2026-01-20 22:42:37.261210 | controller | skipping: [instance]
2026-01-20 22:42:37.288443 | controller |
2026-01-20 22:42:37.288460 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2026-01-20 22:42:37.288467 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.026)       0:00:31.501 *******
2026-01-20 22:42:37.288476 | controller | skipping: [instance]
2026-01-20 22:42:37.316081 | controller |
2026-01-20 22:42:37.316099 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2026-01-20 22:42:37.316107 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.027)       0:00:31.528 *******
2026-01-20 22:42:37.316116 | controller | skipping: [instance]
2026-01-20 22:42:37.341595 | controller |
2026-01-20 22:42:37.341615 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2026-01-20 22:42:37.341623 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.027)       0:00:31.556 *******
2026-01-20 22:42:37.341632 | controller | skipping: [instance]
2026-01-20 22:42:37.363057 | controller |
2026-01-20 22:42:37.363094 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2026-01-20 22:42:37.363109 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.025)       0:00:31.581 *******
2026-01-20 22:42:37.363120 | controller | ok: [instance]
2026-01-20 22:42:37.445313 | controller |
2026-01-20 22:42:37.445365 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2026-01-20 22:42:37.445374 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.021)       0:00:31.603 *******
2026-01-20 22:42:37.445391 | controller | ok: [instance] => (item={'networks': {'ctlplane': {'network': '192.168.122.0/24', 'gateway': '192.168.122.1', 'dns': ['192.168.122.253', '192.168.122.254'], 'search-domain': 'ctlplane.example.local', 'mtu': 1500}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}}}}})
2026-01-20 22:42:37.465157 | controller |
2026-01-20 22:42:37.465187 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2026-01-20 22:42:37.465195 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.081)       0:00:31.684 *******
2026-01-20 22:42:37.465205 | controller | skipping: [instance]
2026-01-20 22:42:37.698902 | controller |
2026-01-20 22:42:37.698944 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2026-01-20 22:42:37.698953 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.020)       0:00:31.705 *******
2026-01-20 22:42:37.698964 | controller | changed: [instance]
2026-01-20 22:42:38.131235 | controller |
2026-01-20 22:42:38.131294 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2026-01-20 22:42:38.131305 | controller | Tuesday 20 January 2026  22:42:37 +0000 (0:00:00.233)       0:00:31.938 *******
2026-01-20 22:42:38.131321 | controller | changed: [instance]
2026-01-20 22:42:38.189674 | controller |
2026-01-20 22:42:38.189694 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2026-01-20 22:42:38.189702 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.431)       0:00:32.370 *******
2026-01-20 22:42:38.189711 | controller | ok: [instance]
2026-01-20 22:42:38.214744 | controller |
2026-01-20 22:42:38.214765 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2026-01-20 22:42:38.214772 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.059)       0:00:32.429 *******
2026-01-20 22:42:38.214782 | controller | ok: [instance]
2026-01-20 22:42:38.649632 | controller |
2026-01-20 22:42:38.649672 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2026-01-20 22:42:38.649680 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.025)       0:00:32.455 *******
2026-01-20 22:42:38.649691 | controller | changed: [instance]
2026-01-20 22:42:38.738641 | controller |
2026-01-20 22:42:38.738682 | controller | TASK [libvirt_manager : Manage networks if needed] *****************************
2026-01-20 22:42:38.738690 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.434)       0:00:32.889 *******
2026-01-20 22:42:38.738700 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks.yml for instance
2026-01-20 22:42:38.820415 | controller |
2026-01-20 22:42:38.820451 | controller | TASK [libvirt_manager : Define the localized variables for performing the tasks here.] ***
2026-01-20 22:42:38.820459 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.088)       0:00:32.978 *******
2026-01-20 22:42:38.820469 | controller | ok: [instance] => (item=public)
2026-01-20 22:42:39.197644 | controller |
2026-01-20 22:42:39.197683 | controller | TASK [libvirt_manager : Ensure networks are defined] ***************************
2026-01-20 22:42:39.197691 | controller | Tuesday 20 January 2026  22:42:38 +0000 (0:00:00.082)       0:00:33.060 *******
2026-01-20 22:42:39.197701 | controller | changed: [instance] => (item=cifmw-public)
2026-01-20 22:42:39.589531 | controller |
2026-01-20 22:42:39.589587 | controller | TASK [libvirt_manager : Ensure networks are created/started] *******************
2026-01-20 22:42:39.589600 | controller | Tuesday 20 January 2026  22:42:39 +0000 (0:00:00.376)       0:00:33.437 *******
2026-01-20 22:42:39.589611 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:42:39.890055 | controller |
2026-01-20 22:42:39.890088 | controller | TASK [libvirt_manager : Ensure networks are active] ****************************
2026-01-20 22:42:39.890103 | controller | Tuesday 20 January 2026  22:42:39 +0000 (0:00:00.388)       0:00:33.825 *******
2026-01-20 22:42:39.890113 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:42:40.188129 | controller |
2026-01-20 22:42:40.188166 | controller | TASK [libvirt_manager : Ensure networks enabled to autostart] ******************
2026-01-20 22:42:40.188178 | controller | Tuesday 20 January 2026  22:42:39 +0000 (0:00:00.304)       0:00:34.130 *******
2026-01-20 22:42:40.188189 | controller | changed: [instance] => (item=cifmw-public)
2026-01-20 22:42:40.256838 | controller |
2026-01-20 22:42:40.256880 | controller | TASK [libvirt_manager : Add a dummy interface to bridges if required] **********
2026-01-20 22:42:40.256889 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.297)       0:00:34.427 *******
2026-01-20 22:42:40.256900 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks_dummy_interfaces.yml for instance
2026-01-20 22:42:40.481698 | controller |
2026-01-20 22:42:40.481736 | controller | TASK [libvirt_manager : Fetch present bridge interfaces] ***********************
2026-01-20 22:42:40.481747 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.068)       0:00:34.496 *******
2026-01-20 22:42:40.481758 | controller | ok: [instance]
2026-01-20 22:42:40.760176 | controller |
2026-01-20 22:42:40.760212 | controller | TASK [libvirt_manager : Fetch bridges ports link info] *************************
2026-01-20 22:42:40.760220 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.224)       0:00:34.721 *******
2026-01-20 22:42:40.760230 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:42:40.858952 | controller |
2026-01-20 22:42:40.858986 | controller | TASK [Create dummy interfaces to ensure bridges are UP] ************************
2026-01-20 22:42:40.858995 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.278)       0:00:34.999 *******
2026-01-20 22:42:40.859005 | controller |
2026-01-20 22:42:40.909606 | controller | TASK [ci_nmstate : Ensure we have needed facts] ********************************
2026-01-20 22:42:40.909647 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.098)       0:00:35.098 *******
2026-01-20 22:42:40.909659 | controller | skipping: [instance]
2026-01-20 22:42:45.915399 | controller |
2026-01-20 22:42:45.915433 | controller | TASK [ci_nmstate : Install required packages on instance] **********************
2026-01-20 22:42:45.915441 | controller | Tuesday 20 January 2026  22:42:40 +0000 (0:00:00.050)       0:00:35.149 *******
2026-01-20 22:42:45.915451 | controller | changed: [instance]
2026-01-20 22:42:46.158955 | controller |
2026-01-20 22:42:46.158990 | controller | TASK [ci_nmstate : Create the target NMstate dump directory] *******************
2026-01-20 22:42:46.158998 | controller | Tuesday 20 January 2026  22:42:45 +0000 (0:00:05.005)       0:00:40.155 *******
2026-01-20 22:42:46.159009 | controller | changed: [instance]
2026-01-20 22:42:46.619077 | controller |
2026-01-20 22:42:46.619117 | controller | TASK [ci_nmstate : Save nmstate state for instance] ****************************
2026-01-20 22:42:46.619125 | controller | Tuesday 20 January 2026  22:42:46 +0000 (0:00:00.243)       0:00:40.398 *******
2026-01-20 22:42:46.619140 | controller | changed: [instance]
2026-01-20 22:42:48.717168 | controller |
2026-01-20 22:42:48.717206 | controller | TASK [ci_nmstate : Apply the desidered state on instance] **********************
2026-01-20 22:42:48.717219 | controller | Tuesday 20 January 2026  22:42:46 +0000 (0:00:00.460)       0:00:40.858 *******
2026-01-20 22:42:48.717229 | controller | changed: [instance]
2026-01-20 22:42:49.127891 | controller |
2026-01-20 22:42:49.127932 | controller | TASK [ci_nmstate : Save nmstate debugging data for instance] *******************
2026-01-20 22:42:49.127941 | controller | Tuesday 20 January 2026  22:42:48 +0000 (0:00:02.097)       0:00:42.956 *******
2026-01-20 22:42:49.127951 | controller | changed: [instance]
2026-01-20 22:42:49.164982 | controller |
2026-01-20 22:42:49.165017 | controller | TASK [Create extra network configuration] **************************************
2026-01-20 22:42:49.165025 | controller | Tuesday 20 January 2026  22:42:49 +0000 (0:00:00.410)       0:00:43.367 *******
2026-01-20 22:42:49.165041 | controller | skipping: [instance]
2026-01-20 22:42:49.199052 | controller |
2026-01-20 22:42:49.199081 | controller | TASK [libvirt_manager : Ensure extra networks is in correct zone] **************
2026-01-20 22:42:49.199090 | controller | Tuesday 20 January 2026  22:42:49 +0000 (0:00:00.037)       0:00:43.404 *******
2026-01-20 22:42:49.199113 | controller | skipping: [instance]
2026-01-20 22:42:49.700491 | controller |
2026-01-20 22:42:49.700530 | controller | TASK [libvirt_manager : Refresh networking facts on host] **********************
2026-01-20 22:42:49.700541 | controller | Tuesday 20 January 2026  22:42:49 +0000 (0:00:00.034)       0:00:43.439 *******
2026-01-20 22:42:49.700551 | controller | ok: [instance]
2026-01-20 22:42:49.860710 | controller |
2026-01-20 22:42:49.860732 | controller | TASK [libvirt_manager : Build needed network/dnsmasq related content] **********
2026-01-20 22:42:49.860740 | controller | Tuesday 20 January 2026  22:42:49 +0000 (0:00:00.500)       0:00:43.939 *******
2026-01-20 22:42:49.860755 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:42:51.321643 | controller |
2026-01-20 22:42:51.321678 | controller | TASK [dnsmasq : Install needed packages] ***************************************
2026-01-20 22:42:51.321691 | controller | Tuesday 20 January 2026  22:42:49 +0000 (0:00:00.160)       0:00:44.100 *******
2026-01-20 22:42:51.321702 | controller | ok: [instance]
2026-01-20 22:42:51.321914 | controller |
2026-01-20 22:42:51.321928 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ******
2026-01-20 22:42:51.321937 | controller | Tuesday 20 January 2026  22:42:51 +0000 (0:00:01.461)       0:00:45.561 *******
2026-01-20 22:42:56.180348 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'})
2026-01-20 22:42:56.464202 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'})
2026-01-20 22:42:56.464264 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'})
2026-01-20 22:42:56.464274 | controller |
2026-01-20 22:42:56.464281 | controller | TASK [dnsmasq : Manage configuration directory] ********************************
2026-01-20 22:42:56.464287 | controller | Tuesday 20 January 2026  22:42:56 +0000 (0:00:04.857)       0:00:50.418 *******
2026-01-20 22:42:56.464299 | controller | changed: [instance]
2026-01-20 22:42:56.938829 | controller |
2026-01-20 22:42:56.938866 | controller | TASK [dnsmasq : Manage systemd unit file] **************************************
2026-01-20 22:42:56.938875 | controller | Tuesday 20 January 2026  22:42:56 +0000 (0:00:00.284)       0:00:50.703 *******
2026-01-20 22:42:56.938889 | controller | changed: [instance]
2026-01-20 22:42:57.408239 | controller |
2026-01-20 22:42:57.408275 | controller | TASK [dnsmasq : Manage base configuration file] ********************************
2026-01-20 22:42:57.408283 | controller | Tuesday 20 January 2026  22:42:56 +0000 (0:00:00.474)       0:00:51.178 *******
2026-01-20 22:42:57.408294 | controller | changed: [instance]
2026-01-20 22:42:57.441846 | controller |
2026-01-20 22:42:57.441869 | controller | TASK [dnsmasq : Render listener configuration] *********************************
2026-01-20 22:42:57.441877 | controller | Tuesday 20 January 2026  22:42:57 +0000 (0:00:00.465)       0:00:51.644 *******
2026-01-20 22:42:57.441886 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance
2026-01-20 22:42:57.987377 | controller |
2026-01-20 22:42:57.987413 | controller | TASK [dnsmasq : Create listener configuration file] ****************************
2026-01-20 22:42:57.987424 | controller | Tuesday 20 January 2026  22:42:57 +0000 (0:00:00.037)       0:00:51.681 *******
2026-01-20 22:42:57.987437 | controller | changed: [instance]
2026-01-20 22:42:58.016897 | controller |
2026-01-20 22:42:58.016931 | controller | TASK [dnsmasq : Remove listener configuration file] ****************************
2026-01-20 22:42:58.016940 | controller | Tuesday 20 January 2026  22:42:57 +0000 (0:00:00.544)       0:00:52.226 *******
2026-01-20 22:42:58.016957 | controller | skipping: [instance]
2026-01-20 22:42:58.056375 | controller |
2026-01-20 22:42:58.056397 | controller | TASK [dnsmasq : Render dns configuration] **************************************
2026-01-20 22:42:58.056405 | controller | Tuesday 20 January 2026  22:42:58 +0000 (0:00:00.029)       0:00:52.256 *******
2026-01-20 22:42:58.056419 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance
2026-01-20 22:42:58.503948 | controller |
2026-01-20 22:42:58.503986 | controller | TASK [dnsmasq : Create dns configuration file] *********************************
2026-01-20 22:42:58.503995 | controller | Tuesday 20 January 2026  22:42:58 +0000 (0:00:00.039)       0:00:52.296 *******
2026-01-20 22:42:58.504012 | controller | changed: [instance]
2026-01-20 22:42:58.527183 | controller |
2026-01-20 22:42:58.527216 | controller | TASK [dnsmasq : Remove dns configuration file] *********************************
2026-01-20 22:42:58.527228 | controller | Tuesday 20 January 2026  22:42:58 +0000 (0:00:00.446)       0:00:52.743 *******
2026-01-20 22:42:58.527238 | controller | skipping: [instance]
2026-01-20 22:42:58.784445 | controller |
2026-01-20 22:42:58.784481 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] ***
2026-01-20 22:42:58.784490 | controller | Tuesday 20 January 2026  22:42:58 +0000 (0:00:00.023)       0:00:52.767 *******
2026-01-20 22:42:58.784500 | controller | ok: [instance] => (item=127.0.0.2)
2026-01-20 22:42:59.625206 | controller |
2026-01-20 22:42:59.625245 | controller | TASK [dnsmasq : Enable and start service] **************************************
2026-01-20 22:42:59.625258 | controller | Tuesday 20 January 2026  22:42:58 +0000 (0:00:00.256)       0:00:53.023 *******
2026-01-20 22:42:59.625270 | controller | changed: [instance]
2026-01-20 22:42:59.650381 | controller |
2026-01-20 22:42:59.650405 | controller | TASK [dnsmasq : Stop service] **************************************************
2026-01-20 22:42:59.650413 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.840)       0:00:53.864 *******
2026-01-20 22:42:59.650423 | controller | skipping: [instance]
2026-01-20 22:42:59.673632 | controller |
2026-01-20 22:42:59.673656 | controller | TASK [dnsmasq : Remove unit file] **********************************************
2026-01-20 22:42:59.673665 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.025)       0:00:53.890 *******
2026-01-20 22:42:59.673678 | controller | skipping: [instance]
2026-01-20 22:42:59.708761 | controller |
2026-01-20 22:42:59.708810 | controller | TASK [dnsmasq : Remove main configuration files] *******************************
2026-01-20 22:42:59.708822 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.023)       0:00:53.913 *******
2026-01-20 22:42:59.708834 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.conf)
2026-01-20 22:42:59.708868 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.d)
2026-01-20 22:42:59.708884 | controller | skipping: [instance]
2026-01-20 22:42:59.708893 | controller |
2026-01-20 22:42:59.708927 | controller | TASK [Create dnsmasq networks] *************************************************
2026-01-20 22:42:59.709038 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.034)       0:00:53.948 *******
2026-01-20 22:42:59.808730 | controller |
2026-01-20 22:42:59.808822 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************
2026-01-20 22:42:59.808947 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.100)       0:00:54.048 *******
2026-01-20 22:42:59.844205 | controller | ok: [instance] => changed=false
2026-01-20 22:42:59.844328 | controller |   msg: All assertions passed
2026-01-20 22:42:59.844471 | controller |
2026-01-20 22:42:59.844610 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] *******************
2026-01-20 22:42:59.844745 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.035)       0:00:54.084 *******
2026-01-20 22:42:59.888727 | controller | ok: [instance] => changed=false
2026-01-20 22:42:59.888872 | controller |   msg: All assertions passed
2026-01-20 22:42:59.888980 | controller |
2026-01-20 22:42:59.889096 | controller | TASK [dnsmasq : Create network] ************************************************
2026-01-20 22:42:59.889220 | controller | Tuesday 20 January 2026  22:42:59 +0000 (0:00:00.044)       0:00:54.129 *******
2026-01-20 22:43:00.410053 | controller | changed: [instance]
2026-01-20 22:43:00.410119 | controller |
2026-01-20 22:43:00.410257 | controller | TASK [dnsmasq : Remove network] ************************************************
2026-01-20 22:43:00.410406 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.518)       0:00:54.647 *******
2026-01-20 22:43:00.431946 | controller | skipping: [instance]
2026-01-20 22:43:00.432068 | controller |
2026-01-20 22:43:00.432206 | controller | TASK [dnsmasq : Remove dhcp host files] ****************************************
2026-01-20 22:43:00.432346 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.024)       0:00:54.672 *******
2026-01-20 22:43:00.460734 | controller | skipping: [instance]
2026-01-20 22:43:00.460861 | controller |
2026-01-20 22:43:00.460992 | controller | TASK [Deploy radvd for IPv6 router advertisements] *****************************
2026-01-20 22:43:00.461114 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.028)       0:00:54.701 *******
2026-01-20 22:43:00.495508 | controller | skipping: [instance]
2026-01-20 22:43:00.495641 | controller |
2026-01-20 22:43:00.495763 | controller | TASK [libvirt_manager : Ensure network is in correct zone] *********************
2026-01-20 22:43:00.495902 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.034)       0:00:54.735 *******
2026-01-20 22:43:00.874461 | controller | changed: [instance] => (item=cifmw-public)
2026-01-20 22:43:00.874575 | controller |
2026-01-20 22:43:00.874739 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2026-01-20 22:43:00.874891 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.378)       0:00:55.114 *******
2026-01-20 22:43:00.910586 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/network_bridge_info_gen.yml for instance => (item=cifmw-public)
2026-01-20 22:43:00.910696 | controller |
2026-01-20 22:43:00.910829 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2026-01-20 22:43:00.910958 | controller | Tuesday 20 January 2026  22:43:00 +0000 (0:00:00.036)       0:00:55.150 *******
2026-01-20 22:43:01.276411 | controller | ok: [instance]
2026-01-20 22:43:01.315896 | controller |
2026-01-20 22:43:01.315929 | controller | TASK [libvirt_manager : Set network_bridge_info fact with network and address] ***
2026-01-20 22:43:01.315939 | controller | Tuesday 20 January 2026  22:43:01 +0000 (0:00:00.364)       0:00:55.515 *******
2026-01-20 22:43:01.315953 | controller | ok: [instance]
2026-01-20 22:43:01.316153 | controller |
2026-01-20 22:43:01.316166 | controller | TASK [libvirt_manager : Output _network_data] **********************************
2026-01-20 22:43:01.316176 | controller | Tuesday 20 January 2026  22:43:01 +0000 (0:00:00.039)       0:00:55.555 *******
2026-01-20 22:43:01.719258 | controller | changed: [instance]
2026-01-20 22:43:02.151698 | controller |
2026-01-20 22:43:02.151736 | controller | TASK [libvirt_manager : Output pub_net] ****************************************
2026-01-20 22:43:02.151748 | controller | Tuesday 20 January 2026  22:43:01 +0000 (0:00:00.403)       0:00:55.959 *******
2026-01-20 22:43:02.151759 | controller | changed: [instance]
2026-01-20 22:43:02.152046 | controller |
2026-01-20 22:43:02.152062 | controller | TASK [libvirt_manager : Output _cifmw_libvirt_manager_layout] ******************
2026-01-20 22:43:02.563283 | controller | Tuesday 20 January 2026  22:43:02 +0000 (0:00:00.431)       0:00:56.391 *******
2026-01-20 22:43:02.563328 | controller | changed: [instance]
2026-01-20 22:43:02.709511 | controller |
2026-01-20 22:43:02.709550 | controller | TASK [libvirt_manager : Expose patch for networking_mapper] ********************
2026-01-20 22:43:02.709580 | controller | Tuesday 20 January 2026  22:43:02 +0000 (0:00:00.411)       0:00:56.803 *******
2026-01-20 22:43:02.709596 | controller | ok: [instance]
2026-01-20 22:43:03.121426 | controller |
2026-01-20 22:43:03.121469 | controller | TASK [libvirt_manager : Save networking_mapper patch] **************************
2026-01-20 22:43:03.121479 | controller | Tuesday 20 January 2026  22:43:02 +0000 (0:00:00.146)       0:00:56.949 *******
2026-01-20 22:43:03.121490 | controller | changed: [instance]
2026-01-20 22:43:03.150102 | controller |
2026-01-20 22:43:03.150125 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2026-01-20 22:43:03.150133 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.412)       0:00:57.361 *******
2026-01-20 22:43:03.150142 | controller | skipping: [instance]
2026-01-20 22:43:03.176888 | controller |
2026-01-20 22:43:03.176917 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2026-01-20 22:43:03.176924 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.028)       0:00:57.390 *******
2026-01-20 22:43:03.176934 | controller | skipping: [instance]
2026-01-20 22:43:03.202543 | controller |
2026-01-20 22:43:03.202586 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2026-01-20 22:43:03.202599 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.026)       0:00:57.416 *******
2026-01-20 22:43:03.202610 | controller | skipping: [instance]
2026-01-20 22:43:03.228971 | controller |
2026-01-20 22:43:03.228999 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2026-01-20 22:43:03.229007 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.025)       0:00:57.442 *******
2026-01-20 22:43:03.229021 | controller | skipping: [instance]
2026-01-20 22:43:03.249402 | controller |
2026-01-20 22:43:03.249428 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2026-01-20 22:43:03.249435 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.026)       0:00:57.468 *******
2026-01-20 22:43:03.249449 | controller | ok: [instance]
2026-01-20 22:43:03.343924 | controller |
2026-01-20 22:43:03.343955 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2026-01-20 22:43:03.343970 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.020)       0:00:57.489 *******
2026-01-20 22:43:03.343982 | controller | ok: [instance] => (item={'networks': {'ctlplane': {'network': '192.168.122.0/24', 'gateway': '192.168.122.1', 'dns': ['192.168.122.253', '192.168.122.254'], 'search-domain': 'ctlplane.example.local', 'mtu': 1500}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}}}}})
2026-01-20 22:43:03.344182 | controller | ok: [instance] => (item={'networks': {'public': {'network-v4': '192.168.100.0/24'}}, 'group-templates': {'computes': {'networks': {'public': None}}}})
2026-01-20 22:43:03.344349 | controller |
2026-01-20 22:43:03.344543 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2026-01-20 22:43:03.344752 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.094)       0:00:57.584 *******
2026-01-20 22:43:03.364956 | controller | skipping: [instance]
2026-01-20 22:43:03.365138 | controller |
2026-01-20 22:43:03.365329 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2026-01-20 22:43:03.365515 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.021)       0:00:57.605 *******
2026-01-20 22:43:03.603948 | controller | ok: [instance]
2026-01-20 22:43:04.068976 | controller |
2026-01-20 22:43:04.069010 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2026-01-20 22:43:04.069018 | controller | Tuesday 20 January 2026  22:43:03 +0000 (0:00:00.238)       0:00:57.843 *******
2026-01-20 22:43:04.069037 | controller | changed: [instance]
2026-01-20 22:43:04.130088 | controller |
2026-01-20 22:43:04.130118 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2026-01-20 22:43:04.130131 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.464)       0:00:58.308 *******
2026-01-20 22:43:04.130142 | controller | ok: [instance]
2026-01-20 22:43:04.157175 | controller |
2026-01-20 22:43:04.157206 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2026-01-20 22:43:04.157214 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.061)       0:00:58.370 *******
2026-01-20 22:43:04.157229 | controller | ok: [instance]
2026-01-20 22:43:04.635192 | controller |
2026-01-20 22:43:04.635232 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2026-01-20 22:43:04.635241 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.027)       0:00:58.397 *******
2026-01-20 22:43:04.635254 | controller | changed: [instance]
2026-01-20 22:43:04.660981 | controller |
2026-01-20 22:43:04.661011 | controller | TASK [libvirt_manager : Be sure to save current state of networking_mapper environment] ***
2026-01-20 22:43:04.661018 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.477)       0:00:58.874 *******
2026-01-20 22:43:04.661029 | controller | ok: [instance]
2026-01-20 22:43:04.682041 | controller |
2026-01-20 22:43:04.682073 | controller | TASK [libvirt_manager : Unset patch] *******************************************
2026-01-20 22:43:04.682081 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.026)       0:00:58.900 *******
2026-01-20 22:43:04.682091 | controller | ok: [instance]
2026-01-20 22:43:04.706080 | controller |
2026-01-20 22:43:04.706108 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_entries fact] ****************
2026-01-20 22:43:04.706116 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.021)       0:00:58.922 *******
2026-01-20 22:43:04.706127 | controller | ok: [instance]
2026-01-20 22:43:04.751071 | controller |
2026-01-20 22:43:04.751105 | controller | TASK [libvirt_manager : Reserve IPs on networks] *******************************
2026-01-20 22:43:04.751113 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.023)       0:00:58.946 *******
2026-01-20 22:43:04.751135 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=ctlplane)
2026-01-20 22:43:04.835818 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=public)
2026-01-20 22:43:04.835848 | controller |
2026-01-20 22:43:04.835856 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2026-01-20 22:43:04.835862 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.044)       0:00:58.990 *******
2026-01-20 22:43:04.835872 | controller | skipping: [instance] => (item=compute-0 - ctlplane)
2026-01-20 22:43:04.961851 | controller | skipping: [instance] => (item=compute-1 - ctlplane)
2026-01-20 22:43:04.961888 | controller | skipping: [instance]
2026-01-20 22:43:04.961896 | controller |
2026-01-20 22:43:04.961902 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2026-01-20 22:43:04.961908 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.084)       0:00:59.075 *******
2026-01-20 22:43:04.961922 | controller | ok: [instance] => (item=compute-0 - public)
2026-01-20 22:43:05.026709 | controller | ok: [instance] => (item=compute-1 - public)
2026-01-20 22:43:05.026748 | controller |
2026-01-20 22:43:05.026758 | controller | TASK [Inject DHCP entries for net {{ net_name }}] ******************************
2026-01-20 22:43:05.026764 | controller | Tuesday 20 January 2026  22:43:04 +0000 (0:00:00.126)       0:00:59.201 *******
2026-01-20 22:43:05.026774 | controller |
2026-01-20 22:43:05.026966 | controller | TASK [dnsmasq : Ensure we have the right data and type] ************************
2026-01-20 22:43:05.027119 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.065)       0:00:59.266 *******
2026-01-20 22:43:05.076318 | controller | ok: [instance]
2026-01-20 22:43:05.076555 | controller |
2026-01-20 22:43:05.076792 | controller | TASK [dnsmasq : Assert we have needed host data] *******************************
2026-01-20 22:43:05.076980 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.049)       0:00:59.316 *******
2026-01-20 22:43:05.141016 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:15:0a:77', 'ips': ['192.168.100.10', ''], 'tag': 'compute'})
2026-01-20 22:43:05.141257 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:bc:d7:45', 'ips': ['192.168.100.11', ''], 'tag': 'compute'})
2026-01-20 22:43:05.141457 | controller |
2026-01-20 22:43:05.141668 | controller | TASK [dnsmasq : Ensure networks exists] ****************************************
2026-01-20 22:43:05.141849 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.064)       0:00:59.381 *******
2026-01-20 22:43:05.193679 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/_check_net_status.yml for instance => (item=public)
2026-01-20 22:43:05.415815 | controller |
2026-01-20 22:43:05.415852 | controller | TASK [dnsmasq : Check network file status] *************************************
2026-01-20 22:43:05.415860 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.052)       0:00:59.433 *******
2026-01-20 22:43:05.415874 | controller | ok: [instance]
2026-01-20 22:43:05.441867 | controller |
2026-01-20 22:43:05.441892 | controller | TASK [dnsmasq : Assert network exists] *****************************************
2026-01-20 22:43:05.441900 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.222)       0:00:59.655 *******
2026-01-20 22:43:05.441910 | controller | ok: [instance]
2026-01-20 22:43:05.463787 | controller |
2026-01-20 22:43:05.463808 | controller | TASK [dnsmasq : Initialize empty dhcp_host_entries] ****************************
2026-01-20 22:43:05.463816 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.026)       0:00:59.681 *******
2026-01-20 22:43:05.463826 | controller | ok: [instance]
2026-01-20 22:43:05.579672 | controller |
2026-01-20 22:43:05.579705 | controller | TASK [dnsmasq : Compute entry] *************************************************
2026-01-20 22:43:05.579713 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.022)       0:00:59.704 *******
2026-01-20 22:43:05.579731 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:15:0a:77', 'ips': ['192.168.100.10', ''], 'tag': 'compute'})
2026-01-20 22:43:05.624343 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:bc:d7:45', 'ips': ['192.168.100.11', ''], 'tag': 'compute'})
2026-01-20 22:43:05.624399 | controller |
2026-01-20 22:43:05.624408 | controller | TASK [dnsmasq : Create add/remove sets] ****************************************
2026-01-20 22:43:05.624414 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.115)       0:00:59.819 *******
2026-01-20 22:43:05.624424 | controller | ok: [instance]
2026-01-20 22:43:06.444703 | controller |
2026-01-20 22:43:06.444742 | controller | TASK [dnsmasq : Add DHCP entries] **********************************************
2026-01-20 22:43:06.444753 | controller | Tuesday 20 January 2026  22:43:05 +0000 (0:00:00.044)       0:00:59.863 *******
2026-01-20 22:43:06.444765 | controller | changed: [instance] => (item={'file': 'public_compute-0_52:54:00:15:0a:77', 'entry': 'set:compute,52:54:00:15:0a:77,192.168.100.10,compute-0', 'state': 'present'})
2026-01-20 22:43:06.470456 | controller | changed: [instance] => (item={'file': 'public_compute-1_52:54:01:bc:d7:45', 'entry': 'set:compute,52:54:01:bc:d7:45,192.168.100.11,compute-1', 'state': 'present'})
2026-01-20 22:43:06.470500 | controller |
2026-01-20 22:43:06.470509 | controller | TASK [dnsmasq : Remove DHCP entries] *******************************************
2026-01-20 22:43:06.470515 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.820)       0:01:00.684 *******
2026-01-20 22:43:06.470530 | controller | skipping: [instance]
2026-01-20 22:43:06.620029 | controller |
2026-01-20 22:43:06.620061 | controller | TASK [libvirt_manager : Create per-network and .utility DNS entries] ***********
2026-01-20 22:43:06.620069 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.026)       0:01:00.710 *******
2026-01-20 22:43:06.620083 | controller | ok: [instance] => (item=compute-0)
2026-01-20 22:43:06.689948 | controller | ok: [instance] => (item=compute-1)
2026-01-20 22:43:06.689982 | controller |
2026-01-20 22:43:06.689990 | controller | TASK [Inject VMs in the .utility zone] *****************************************
2026-01-20 22:43:06.689995 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.149)       0:01:00.859 *******
2026-01-20 22:43:06.690009 | controller |
2026-01-20 22:43:06.733307 | controller | TASK [dnsmasq : Assert we have needed host record data] ************************
2026-01-20 22:43:06.733337 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.070)       0:01:00.929 *******
2026-01-20 22:43:06.733351 | controller | ok: [instance]
2026-01-20 22:43:06.849539 | controller |
2026-01-20 22:43:06.849594 | controller | TASK [dnsmasq : Assert each address element have needed data] ******************
2026-01-20 22:43:06.849606 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.043)       0:01:00.973 *******
2026-01-20 22:43:06.849621 | controller | ok: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2026-01-20 22:43:08.338580 | controller | ok: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2026-01-20 22:43:08.338619 | controller | ok: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2026-01-20 22:43:08.338627 | controller | ok: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2026-01-20 22:43:08.338634 | controller | ok: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2026-01-20 22:43:08.338639 | controller | ok: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2026-01-20 22:43:08.338645 | controller |
2026-01-20 22:43:08.338650 | controller | TASK [dnsmasq : Add/Remove address] ********************************************
2026-01-20 22:43:08.338656 | controller | Tuesday 20 January 2026  22:43:06 +0000 (0:00:00.115)       0:01:01.088 *******
2026-01-20 22:43:08.338666 | controller | changed: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2026-01-20 22:43:08.359689 | controller | changed: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2026-01-20 22:43:08.359718 | controller | changed: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2026-01-20 22:43:08.359727 | controller | changed: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2026-01-20 22:43:08.359732 | controller | changed: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2026-01-20 22:43:08.359738 | controller | changed: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2026-01-20 22:43:08.359743 | controller |
2026-01-20 22:43:08.359749 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_options fact] ****************
2026-01-20 22:43:08.359755 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:01.489)       0:01:02.577 *******
2026-01-20 22:43:08.359764 | controller | ok: [instance]
2026-01-20 22:43:08.398497 | controller |
2026-01-20 22:43:08.398524 | controller | TASK [libvirt_manager : Collect DHCP options from VM definitions] **************
2026-01-20 22:43:08.398532 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:00.021)       0:01:02.599 *******
2026-01-20 22:43:08.398542 | controller | skipping: [instance] => (item=compute)
2026-01-20 22:43:08.430861 | controller | skipping: [instance]
2026-01-20 22:43:08.430883 | controller |
2026-01-20 22:43:08.430890 | controller | TASK [libvirt_manager : Generate DHCP option configuration for VM types] *******
2026-01-20 22:43:08.430896 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:00.038)       0:01:02.638 *******
2026-01-20 22:43:08.430909 | controller | skipping: [instance]
2026-01-20 22:43:08.852591 | controller |
2026-01-20 22:43:08.852628 | controller | TASK [libvirt_manager : Ensure some domains are local] *************************
2026-01-20 22:43:08.852641 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:00.032)       0:01:02.671 *******
2026-01-20 22:43:08.852652 | controller | changed: [instance]
2026-01-20 22:43:09.746865 | controller |
2026-01-20 22:43:09.746893 | controller | TASK [libvirt_manager : Ensure dnsmasq is reloaded now] ************************
2026-01-20 22:43:09.746901 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:00.409)       0:01:03.080 *******
2026-01-20 22:43:09.746907 | controller |
2026-01-20 22:43:09.746912 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2026-01-20 22:43:09.746917 | controller | Tuesday 20 January 2026  22:43:08 +0000 (0:00:00.011)       0:01:03.091 *******
2026-01-20 22:43:09.746927 | controller | changed: [instance]
2026-01-20 22:43:10.109257 | controller |
2026-01-20 22:43:10.109287 | controller | RUNNING HANDLER [dnsmasq : Restart dnsmasq] ************************************
2026-01-20 22:43:10.109295 | controller | Tuesday 20 January 2026  22:43:09 +0000 (0:00:00.894)       0:01:03.986 *******
2026-01-20 22:43:10.109305 | controller | changed: [instance]
2026-01-20 22:43:10.482418 | controller |
2026-01-20 22:43:10.482452 | controller | RUNNING HANDLER [dnsmasq : Reload dnsmasq] *************************************
2026-01-20 22:43:10.482460 | controller | Tuesday 20 January 2026  22:43:10 +0000 (0:00:00.362)       0:01:04.349 *******
2026-01-20 22:43:10.482470 | controller | changed: [instance]
2026-01-20 22:43:10.954889 | controller |
2026-01-20 22:43:10.954952 | controller | TASK [libvirt_manager : Create group inventories] ******************************
2026-01-20 22:43:10.954962 | controller | Tuesday 20 January 2026  22:43:10 +0000 (0:00:00.373)       0:01:04.722 *******
2026-01-20 22:43:10.954976 | controller | changed: [instance] => (item=compute)
2026-01-20 22:43:11.034963 | controller |
2026-01-20 22:43:11.035032 | controller | TASK [libvirt_manager : Create "all" group inventory file] *********************
2026-01-20 22:43:11.035043 | controller | Tuesday 20 January 2026  22:43:10 +0000 (0:00:00.471)       0:01:05.193 *******
2026-01-20 22:43:11.035057 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_all_group_inventory.yml for instance
2026-01-20 22:43:11.254715 | controller |
2026-01-20 22:43:11.254776 | controller | TASK [libvirt_manager : Check if all-group.yml already exists] *****************
2026-01-20 22:43:11.254790 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.079)       0:01:05.273 *******
2026-01-20 22:43:11.254804 | controller | ok: [instance]
2026-01-20 22:43:11.282527 | controller |
2026-01-20 22:43:11.282582 | controller | TASK [libvirt_manager : Slurp existing all-group.yml if it exists] *************
2026-01-20 22:43:11.282594 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.219)       0:01:05.493 *******
2026-01-20 22:43:11.282628 | controller | skipping: [instance]
2026-01-20 22:43:11.751666 | controller |
2026-01-20 22:43:11.751716 | controller | TASK [libvirt_manager : Create new "all" group inventory file from template] ***
2026-01-20 22:43:11.751726 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.028)       0:01:05.522 *******
2026-01-20 22:43:11.751737 | controller | changed: [instance]
2026-01-20 22:43:11.752077 | controller |
2026-01-20 22:43:11.752092 | controller | TASK [libvirt_manager : Slurp newly created all-group.yml] *********************
2026-01-20 22:43:11.776260 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.469)       0:01:05.991 *******
2026-01-20 22:43:11.776288 | controller | skipping: [instance]
2026-01-20 22:43:11.799778 | controller |
2026-01-20 22:43:11.799798 | controller | TASK [libvirt_manager : Write merged all-group.yml] ****************************
2026-01-20 22:43:11.799805 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.024)       0:01:06.016 *******
2026-01-20 22:43:11.799814 | controller | skipping: [instance]
2026-01-20 22:43:11.800109 | controller |
2026-01-20 22:43:11.800130 | controller | TASK [libvirt_manager : Ensure storage pool is present.] ***********************
2026-01-20 22:43:11.850521 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.023)       0:01:06.039 *******
2026-01-20 22:43:11.850555 | controller | skipping: [instance]
2026-01-20 22:43:11.957919 | controller |
2026-01-20 22:43:11.957956 | controller | TASK [libvirt_manager : Ensure images are present] *****************************
2026-01-20 22:43:11.957965 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.050)       0:01:06.090 *******
2026-01-20 22:43:11.957975 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/get_image.yml for instance => (item=compute)
2026-01-20 22:43:11.984284 | controller |
2026-01-20 22:43:11.984309 | controller | TASK [libvirt_manager : Ensure directory exists] *******************************
2026-01-20 22:43:11.984317 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.107)       0:01:06.197 *******
2026-01-20 22:43:11.984326 | controller | skipping: [instance]
2026-01-20 22:43:12.011408 | controller |
2026-01-20 22:43:12.011434 | controller | TASK [libvirt_manager : Check if base image exists] ****************************
2026-01-20 22:43:12.011442 | controller | Tuesday 20 January 2026  22:43:11 +0000 (0:00:00.026)       0:01:06.224 *******
2026-01-20 22:43:12.011455 | controller | skipping: [instance]
2026-01-20 22:43:12.037453 | controller |
2026-01-20 22:43:12.037478 | controller | TASK [libvirt_manager : Download base image] ***********************************
2026-01-20 22:43:12.037487 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.026)       0:01:06.250 *******
2026-01-20 22:43:12.037496 | controller | skipping: [instance]
2026-01-20 22:43:12.037844 | controller |
2026-01-20 22:43:12.037868 | controller | TASK [libvirt_manager : Check image] *******************************************
2026-01-20 22:43:12.063242 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.026)       0:01:06.277 *******
2026-01-20 22:43:12.063267 | controller | skipping: [instance]
2026-01-20 22:43:12.093688 | controller |
2026-01-20 22:43:12.093710 | controller | TASK [libvirt_manager : Assert image status] ***********************************
2026-01-20 22:43:12.093723 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.025)       0:01:06.303 *******
2026-01-20 22:43:12.093732 | controller | skipping: [instance]
2026-01-20 22:43:12.120483 | controller |
2026-01-20 22:43:12.120505 | controller | TASK [libvirt_manager : Ensure image access rights] ****************************
2026-01-20 22:43:12.120513 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.030)       0:01:06.333 *******
2026-01-20 22:43:12.120522 | controller | skipping: [instance]
2026-01-20 22:43:12.370890 | controller |
2026-01-20 22:43:12.370958 | controller | TASK [libvirt_manager : Get ssh key state] *************************************
2026-01-20 22:43:12.370967 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.026)       0:01:06.360 *******
2026-01-20 22:43:12.370981 | controller | ok: [instance]
2026-01-20 22:43:12.883479 | controller |
2026-01-20 22:43:12.883527 | controller | TASK [libvirt_manager : Create temporary ssh keypair] **************************
2026-01-20 22:43:12.883541 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.249)       0:01:06.609 *******
2026-01-20 22:43:12.883554 | controller | changed: [instance]
2026-01-20 22:43:13.223666 | controller |
2026-01-20 22:43:13.223745 | controller | TASK [libvirt_manager : Slurp public key for later use] ************************
2026-01-20 22:43:13.223755 | controller | Tuesday 20 January 2026  22:43:12 +0000 (0:00:00.513)       0:01:07.122 *******
2026-01-20 22:43:13.223770 | controller | ok: [instance]
2026-01-20 22:43:13.445722 | controller |
2026-01-20 22:43:13.445794 | controller | TASK [libvirt_manager : Slurp private key for later use] ***********************
2026-01-20 22:43:13.445804 | controller | Tuesday 20 January 2026  22:43:13 +0000 (0:00:00.339)       0:01:07.462 *******
2026-01-20 22:43:13.445817 | controller | ok: [instance]
2026-01-20 22:43:13.896526 | controller |
2026-01-20 22:43:13.896595 | controller | TASK [libvirt_manager : Inject cifmw_reproducer_key.pub in hypervisor authorized_keys] ***
2026-01-20 22:43:13.896605 | controller | Tuesday 20 January 2026  22:43:13 +0000 (0:00:00.222)       0:01:07.684 *******
2026-01-20 22:43:13.896618 | controller | changed: [instance]
2026-01-20 22:43:13.921321 | controller |
2026-01-20 22:43:13.921373 | controller | TASK [libvirt_manager : Create fact holding network data for VMs] **************
2026-01-20 22:43:13.921385 | controller | Tuesday 20 January 2026  22:43:13 +0000 (0:00:00.451)       0:01:08.136 *******
2026-01-20 22:43:13.921397 | controller | ok: [instance]
2026-01-20 22:43:14.174205 | controller |
2026-01-20 22:43:14.174247 | controller | TASK [libvirt_manager : List existing networks] ********************************
2026-01-20 22:43:14.174260 | controller | Tuesday 20 January 2026  22:43:13 +0000 (0:00:00.024)       0:01:08.160 *******
2026-01-20 22:43:14.174275 | controller | ok: [instance]
2026-01-20 22:43:14.563440 | controller |
2026-01-20 22:43:14.563477 | controller | TASK [libvirt_manager : Gather pool fact] **************************************
2026-01-20 22:43:14.563485 | controller | Tuesday 20 January 2026  22:43:14 +0000 (0:00:00.253)       0:01:08.413 *******
2026-01-20 22:43:14.563499 | controller | ok: [instance]
2026-01-20 22:43:14.661325 | controller |
2026-01-20 22:43:14.661358 | controller | TASK [libvirt_manager : Create and run VMs] ************************************
2026-01-20 22:43:14.661366 | controller | Tuesday 20 January 2026  22:43:14 +0000 (0:00:00.389)       0:01:08.803 *******
2026-01-20 22:43:14.661376 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_vms.yml for instance => (item={'key': 'compute-0', 'value': 'compute'})
2026-01-20 22:43:14.947962 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_vms.yml for instance => (item={'key': 'compute-1', 'value': 'compute'})
2026-01-20 22:43:14.948002 | controller |
2026-01-20 22:43:14.948010 | controller | TASK [libvirt_manager : Create VM image for compute-0] *************************
2026-01-20 22:43:14.948017 | controller | Tuesday 20 January 2026  22:43:14 +0000 (0:00:00.097)       0:01:08.900 *******
2026-01-20 22:43:14.948027 | controller | changed: [instance]
2026-01-20 22:43:15.186800 | controller |
2026-01-20 22:43:15.186842 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-0] ********
2026-01-20 22:43:15.186853 | controller | Tuesday 20 January 2026  22:43:14 +0000 (0:00:00.286)       0:01:09.187 *******
2026-01-20 22:43:15.186863 | controller | changed: [instance]
2026-01-20 22:43:15.650877 | controller |
2026-01-20 22:43:15.650911 | controller | TASK [libvirt_manager : Define VMs for type compute-0] *************************
2026-01-20 22:43:15.650919 | controller | Tuesday 20 January 2026  22:43:15 +0000 (0:00:00.238)       0:01:09.426 *******
2026-01-20 22:43:15.650929 | controller | changed: [instance]
2026-01-20 22:43:15.680231 | controller |
2026-01-20 22:43:15.680271 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-0] ***********
2026-01-20 22:43:15.680280 | controller | Tuesday 20 January 2026  22:43:15 +0000 (0:00:00.464)       0:01:09.890 *******
2026-01-20 22:43:15.680300 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2026-01-20 22:43:15.720391 | controller |
2026-01-20 22:43:15.720441 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2026-01-20 22:43:15.720450 | controller | Tuesday 20 January 2026  22:43:15 +0000 (0:00:00.029)       0:01:09.920 *******
2026-01-20 22:43:15.720460 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2026-01-20 22:43:16.016666 | controller |
2026-01-20 22:43:16.016705 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2026-01-20 22:43:16.016714 | controller | Tuesday 20 January 2026  22:43:15 +0000 (0:00:00.040)       0:01:09.960 *******
2026-01-20 22:43:16.016727 | controller | ok: [instance]
2026-01-20 22:43:16.076847 | controller |
2026-01-20 22:43:16.076883 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2026-01-20 22:43:16.076892 | controller | Tuesday 20 January 2026  22:43:16 +0000 (0:00:00.296)       0:01:10.256 *******
2026-01-20 22:43:16.076903 | controller | ok: [instance] => (item=default)
2026-01-20 22:43:16.361437 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:43:16.361474 | controller | ok: [instance] => (item=crc)
2026-01-20 22:43:16.361484 | controller |
2026-01-20 22:43:16.361490 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2026-01-20 22:43:16.361496 | controller | Tuesday 20 January 2026  22:43:16 +0000 (0:00:00.059)       0:01:10.316 *******
2026-01-20 22:43:16.361506 | controller | ok: [instance]
2026-01-20 22:43:16.632472 | controller |
2026-01-20 22:43:16.632508 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2026-01-20 22:43:16.632517 | controller | Tuesday 20 January 2026  22:43:16 +0000 (0:00:00.284)       0:01:10.601 *******
2026-01-20 22:43:16.632527 | controller | ok: [instance]
2026-01-20 22:43:16.998209 | controller |
2026-01-20 22:43:16.998251 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-0] ************
2026-01-20 22:43:16.998260 | controller | Tuesday 20 January 2026  22:43:16 +0000 (0:00:00.270)       0:01:10.872 *******
2026-01-20 22:43:16.998271 | controller | changed: [instance]
2026-01-20 22:43:17.020357 | controller |
2026-01-20 22:43:17.020381 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-0] *****
2026-01-20 22:43:17.020389 | controller | Tuesday 20 January 2026  22:43:16 +0000 (0:00:00.365)       0:01:11.238 *******
2026-01-20 22:43:17.020399 | controller | skipping: [instance]
2026-01-20 22:43:17.050960 | controller |
2026-01-20 22:43:17.050983 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-0] ********
2026-01-20 22:43:17.050991 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.022)       0:01:11.260 *******
2026-01-20 22:43:17.051000 | controller | skipping: [instance]
2026-01-20 22:43:17.080932 | controller |
2026-01-20 22:43:17.080953 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-0] **************
2026-01-20 22:43:17.080960 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.030)       0:01:11.291 *******
2026-01-20 22:43:17.080969 | controller | skipping: [instance]
2026-01-20 22:43:17.111446 | controller |
2026-01-20 22:43:17.111474 | controller | TASK [libvirt_manager : Attach volumes for VM compute-0] ***********************
2026-01-20 22:43:17.111485 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.030)       0:01:11.321 *******
2026-01-20 22:43:17.111498 | controller | skipping: [instance]
2026-01-20 22:43:17.357437 | controller |
2026-01-20 22:43:17.357470 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2026-01-20 22:43:17.357478 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.030)       0:01:11.351 *******
2026-01-20 22:43:17.357488 | controller | changed: [instance]
2026-01-20 22:43:17.400989 | controller |
2026-01-20 22:43:17.401018 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2026-01-20 22:43:17.401026 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.246)       0:01:11.597 *******
2026-01-20 22:43:17.401036 | controller | ok: [instance]
2026-01-20 22:43:17.424639 | controller |
2026-01-20 22:43:17.424663 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2026-01-20 22:43:17.424671 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.043)       0:01:11.640 *******
2026-01-20 22:43:17.424680 | controller | skipping: [instance]
2026-01-20 22:43:17.448862 | controller |
2026-01-20 22:43:17.448882 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2026-01-20 22:43:17.448889 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.024)       0:01:11.664 *******
2026-01-20 22:43:17.448898 | controller | skipping: [instance]
2026-01-20 22:43:17.510302 | controller |
2026-01-20 22:43:17.510332 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2026-01-20 22:43:17.510340 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.024)       0:01:11.689 *******
2026-01-20 22:43:17.510350 | controller | skipping: [instance]
2026-01-20 22:43:17.540406 | controller |
2026-01-20 22:43:17.540445 | controller | TASK [libvirt_manager : Configure boot order for compute-0] ********************
2026-01-20 22:43:17.540454 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.061)       0:01:11.750 *******
2026-01-20 22:43:17.540463 | controller | skipping: [instance]
2026-01-20 22:43:17.830149 | controller |
2026-01-20 22:43:17.830205 | controller | TASK [libvirt_manager : Create VM image for compute-1] *************************
2026-01-20 22:43:17.830215 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.030)       0:01:11.780 *******
2026-01-20 22:43:17.830229 | controller | changed: [instance]
2026-01-20 22:43:18.112917 | controller |
2026-01-20 22:43:18.112950 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-1] ********
2026-01-20 22:43:18.112957 | controller | Tuesday 20 January 2026  22:43:17 +0000 (0:00:00.288)       0:01:12.069 *******
2026-01-20 22:43:18.112967 | controller | changed: [instance]
2026-01-20 22:43:18.456542 | controller |
2026-01-20 22:43:18.456596 | controller | TASK [libvirt_manager : Define VMs for type compute-1] *************************
2026-01-20 22:43:18.456605 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.283)       0:01:12.352 *******
2026-01-20 22:43:18.456615 | controller | changed: [instance]
2026-01-20 22:43:18.487922 | controller |
2026-01-20 22:43:18.487950 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-1] ***********
2026-01-20 22:43:18.487958 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.342)       0:01:12.695 *******
2026-01-20 22:43:18.487968 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2026-01-20 22:43:18.526724 | controller |
2026-01-20 22:43:18.526803 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2026-01-20 22:43:18.526826 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.032)       0:01:12.727 *******
2026-01-20 22:43:18.526839 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2026-01-20 22:43:18.526874 | controller |
2026-01-20 22:43:18.526884 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2026-01-20 22:43:18.526893 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.038)       0:01:12.766 *******
2026-01-20 22:43:18.826747 | controller | ok: [instance]
2026-01-20 22:43:18.881873 | controller |
2026-01-20 22:43:18.881923 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2026-01-20 22:43:18.881936 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.299)       0:01:13.066 *******
2026-01-20 22:43:18.881949 | controller | ok: [instance] => (item=default)
2026-01-20 22:43:18.882212 | controller | ok: [instance] => (item=cifmw-public)
2026-01-20 22:43:18.882418 | controller | ok: [instance] => (item=crc)
2026-01-20 22:43:18.882677 | controller |
2026-01-20 22:43:18.882869 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2026-01-20 22:43:18.883075 | controller | Tuesday 20 January 2026  22:43:18 +0000 (0:00:00.055)       0:01:13.121 *******
2026-01-20 22:43:19.195893 | controller | ok: [instance]
2026-01-20 22:43:19.433906 | controller |
2026-01-20 22:43:19.433945 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2026-01-20 22:43:19.433954 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.310)       0:01:13.432 *******
2026-01-20 22:43:19.433970 | controller | ok: [instance]
2026-01-20 22:43:19.771445 | controller |
2026-01-20 22:43:19.771479 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-1] ************
2026-01-20 22:43:19.771488 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.240)       0:01:13.673 *******
2026-01-20 22:43:19.771498 | controller | changed: [instance]
2026-01-20 22:43:19.792503 | controller |
2026-01-20 22:43:19.792533 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-1] *****
2026-01-20 22:43:19.792541 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.338)       0:01:14.011 *******
2026-01-20 22:43:19.792557 | controller | skipping: [instance]
2026-01-20 22:43:19.821812 | controller |
2026-01-20 22:43:19.821841 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-1] ********
2026-01-20 22:43:19.821853 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.021)       0:01:14.032 *******
2026-01-20 22:43:19.821864 | controller | skipping: [instance]
2026-01-20 22:43:19.850984 | controller |
2026-01-20 22:43:19.851015 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-1] **************
2026-01-20 22:43:19.851022 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.029)       0:01:14.062 *******
2026-01-20 22:43:19.851032 | controller | skipping: [instance]
2026-01-20 22:43:19.878549 | controller |
2026-01-20 22:43:19.878586 | controller | TASK [libvirt_manager : Attach volumes for VM compute-1] ***********************
2026-01-20 22:43:19.878594 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.028)       0:01:14.091 *******
2026-01-20 22:43:19.878603 | controller | skipping: [instance]
2026-01-20 22:43:20.131291 | controller |
2026-01-20 22:43:20.131324 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2026-01-20 22:43:20.131332 | controller | Tuesday 20 January 2026  22:43:19 +0000 (0:00:00.027)       0:01:14.118 *******
2026-01-20 22:43:20.131343 | controller | changed: [instance]
2026-01-20 22:43:20.172962 | controller |
2026-01-20 22:43:20.173001 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2026-01-20 22:43:20.173012 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.252)       0:01:14.371 *******
2026-01-20 22:43:20.173023 | controller | ok: [instance]
2026-01-20 22:43:20.196286 | controller |
2026-01-20 22:43:20.196315 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2026-01-20 22:43:20.196328 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.041)       0:01:14.412 *******
2026-01-20 22:43:20.196338 | controller | skipping: [instance]
2026-01-20 22:43:20.221112 | controller |
2026-01-20 22:43:20.221135 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2026-01-20 22:43:20.221142 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.023)       0:01:14.436 *******
2026-01-20 22:43:20.221151 | controller | skipping: [instance]
2026-01-20 22:43:20.271481 | controller |
2026-01-20 22:43:20.271511 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2026-01-20 22:43:20.271519 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.024)       0:01:14.461 *******
2026-01-20 22:43:20.271528 | controller | skipping: [instance]
2026-01-20 22:43:20.299397 | controller |
2026-01-20 22:43:20.299422 | controller | TASK [libvirt_manager : Configure boot order for compute-1] ********************
2026-01-20 22:43:20.299453 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.050)       0:01:14.511 *******
2026-01-20 22:43:20.299470 | controller | skipping: [instance]
2026-01-20 22:43:20.346744 | controller |
2026-01-20 22:43:20.346778 | controller | TASK [libvirt_manager : Start (power-on) VMs] **********************************
2026-01-20 22:43:20.346787 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.027)       0:01:14.539 *******
2026-01-20 22:43:20.346800 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/start_vms.yml for instance
2026-01-20 22:43:20.622396 | controller |
2026-01-20 22:43:20.622444 | controller | TASK [libvirt_manager : Refresh oooq_pool before starting VMs] *****************
2026-01-20 22:43:20.622458 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.047)       0:01:14.586 *******
2026-01-20 22:43:20.622470 | controller | ok: [instance] => (item=crc)
2026-01-20 22:43:21.674893 | controller |
2026-01-20 22:43:21.674929 | controller | TASK [libvirt_manager : Start VMs for type {{ vm_type }}] **********************
2026-01-20 22:43:21.674938 | controller | Tuesday 20 January 2026  22:43:20 +0000 (0:00:00.275)       0:01:14.861 *******
2026-01-20 22:43:21.674948 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2026-01-20 22:43:21.740317 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2026-01-20 22:43:21.740350 | controller | skipping: [instance]
2026-01-20 22:43:21.740362 | controller |
2026-01-20 22:43:21.740369 | controller | TASK [libvirt_manager : Wait for SSH on started VMs] ***************************
2026-01-20 22:43:21.740374 | controller | Tuesday 20 January 2026  22:43:21 +0000 (0:00:01.052)       0:01:15.914 *******
2026-01-20 22:43:21.740384 | controller | skipping: [instance] => (item=compute-0.utility)
2026-01-20 22:43:21.775785 | controller | skipping: [instance] => (item=compute-1.utility)
2026-01-20 22:43:21.775821 | controller | skipping: [instance]
2026-01-20 22:43:21.775830 | controller |
2026-01-20 22:43:21.775839 | controller | TASK [libvirt_manager : Ensure we get SSH on nodes] ****************************
2026-01-20 22:43:21.775846 | controller | Tuesday 20 January 2026  22:43:21 +0000 (0:00:00.065)       0:01:15.979 *******
2026-01-20 22:43:21.775856 | controller | skipping: [instance] => (item={'changed': False, 'skipped': True, 'skip_reason': 'Conditional result was False', 'false_condition': "vm_data.disk_file_name != 'blank'", '_vm': {'key': 'compute-0', 'value': 'compute'}, 'ansible_loop_var': '_vm'})
2026-01-20 22:43:21.826512 | controller | skipping: [instance] => (item={'changed': False, 'skipped': True, 'skip_reason': 'Conditional result was False', 'false_condition': "vm_data.disk_file_name != 'blank'", '_vm': {'key': 'compute-1', 'value': 'compute'}, 'ansible_loop_var': '_vm'})
2026-01-20 22:43:21.826543 | controller | skipping: [instance]
2026-01-20 22:43:21.826551 | controller |
2026-01-20 22:43:21.826557 | controller | TASK [libvirt_manager : Configure managed VMs] *********************************
2026-01-20 22:43:21.826580 | controller | Tuesday 20 January 2026  22:43:21 +0000 (0:00:00.035)       0:01:16.015 *******
2026-01-20 22:43:21.826591 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2026-01-20 22:43:21.877108 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2026-01-20 22:43:21.877147 | controller | skipping: [instance]
2026-01-20 22:43:21.877156 | controller |
2026-01-20 22:43:21.877163 | controller | TASK [Create VBMC entity] ******************************************************
2026-01-20 22:43:21.877168 | controller | Tuesday 20 January 2026  22:43:21 +0000 (0:00:00.050)       0:01:16.065 *******
2026-01-20 22:43:21.877186 | controller | skipping: [instance] => (item=compute-0)
2026-01-20 22:43:22.123472 | controller | skipping: [instance] => (item=compute-1)
2026-01-20 22:43:22.123513 | controller | skipping: [instance]
2026-01-20 22:43:22.123521 | controller |
2026-01-20 22:43:22.123528 | controller | TASK [libvirt_manager : List running virtual machines.] ************************
2026-01-20 22:43:22.123534 | controller | Tuesday 20 January 2026  22:43:21 +0000 (0:00:00.050)       0:01:16.116 *******
2026-01-20 22:43:22.123544 | controller | ok: [instance]
2026-01-20 22:43:22.508512 | controller |
2026-01-20 22:43:22.508552 | controller | TASK [libvirt_manager : Dump UUIDs] ********************************************
2026-01-20 22:43:22.508576 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.246)       0:01:16.363 *******
2026-01-20 22:43:22.508598 | controller | changed: [instance]
2026-01-20 22:43:22.544381 | controller |
2026-01-20 22:43:22.544401 | controller | TASK [Ensure fresh vbmc listing] ***********************************************
2026-01-20 22:43:22.544409 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.384)       0:01:16.748 *******
2026-01-20 22:43:22.544418 | controller | skipping: [instance]
2026-01-20 22:43:22.578847 | controller |
2026-01-20 22:43:22.578875 | controller | TASK [libvirt_manager : Update vbmc related fact] ******************************
2026-01-20 22:43:22.578883 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.036)       0:01:16.784 *******
2026-01-20 22:43:22.578892 | controller | skipping: [instance]
2026-01-20 22:43:22.615801 | controller |
2026-01-20 22:43:22.615832 | controller | TASK [libvirt_manager : Dump vbmc known hosts] *********************************
2026-01-20 22:43:22.615848 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.034)       0:01:16.818 *******
2026-01-20 22:43:22.615862 | controller | skipping: [instance]
2026-01-20 22:43:22.647904 | controller |
2026-01-20 22:43:22.647928 | controller | TASK [libvirt_manager : Copy authorized_keys] **********************************
2026-01-20 22:43:22.647943 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.036)       0:01:16.855 *******
2026-01-20 22:43:22.647956 | controller | skipping: [instance]
2026-01-20 22:43:22.680495 | controller |
2026-01-20 22:43:22.680516 | controller | TASK [libvirt_manager : Enable root access on CRC] *****************************
2026-01-20 22:43:22.680524 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.032)       0:01:16.887 *******
2026-01-20 22:43:22.680533 | controller | skipping: [instance]
2026-01-20 22:43:22.762775 | controller |
2026-01-20 22:43:22.762799 | controller | TASK [Generate baremetal-info fact] ********************************************
2026-01-20 22:43:22.762808 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.032)       0:01:16.920 *******
2026-01-20 22:43:22.762816 | controller |
2026-01-20 22:43:23.281650 | controller | TASK [reproducer : Ensure directories exist] ***********************************
2026-01-20 22:43:23.281685 | controller | Tuesday 20 January 2026  22:43:22 +0000 (0:00:00.082)       0:01:17.002 *******
2026-01-20 22:43:23.281698 | controller | changed: [instance] => (item=parameters)
2026-01-20 22:43:23.282233 | controller | ok: [instance] => (item=artifacts)
2026-01-20 22:43:23.321780 | controller |
2026-01-20 22:43:23.321800 | controller | TASK [reproducer : Convert VBMC list into a dict for better usage] *************
2026-01-20 22:43:23.321808 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.519)       0:01:17.521 *******
2026-01-20 22:43:23.321817 | controller | skipping: [instance]
2026-01-20 22:43:23.547001 | controller |
2026-01-20 22:43:23.547041 | controller | TASK [reproducer : Check if baremetal-info.yml exists] *************************
2026-01-20 22:43:23.547054 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.039)       0:01:17.561 *******
2026-01-20 22:43:23.547064 | controller | ok: [instance]
2026-01-20 22:43:23.566891 | controller |
2026-01-20 22:43:23.566908 | controller | TASK [reproducer : Get content of baremetal-info file] *************************
2026-01-20 22:43:23.566915 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.224)       0:01:17.786 *******
2026-01-20 22:43:23.566924 | controller | skipping: [instance]
2026-01-20 22:43:23.602076 | controller |
2026-01-20 22:43:23.602096 | controller | TASK [reproducer : Interpret remote file content as yaml] **********************
2026-01-20 22:43:23.602103 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.020)       0:01:17.806 *******
2026-01-20 22:43:23.602112 | controller | skipping: [instance]
2026-01-20 22:43:23.634995 | controller |
2026-01-20 22:43:23.635015 | controller | TASK [reproducer : Slurp content of: /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2026-01-20 22:43:23.635022 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.035)       0:01:17.842 *******
2026-01-20 22:43:23.635031 | controller | skipping: [instance]
2026-01-20 22:43:23.659405 | controller |
2026-01-20 22:43:23.659429 | controller | TASK [reproducer : Set cifmw_libvirt_manager_mac_map fact from /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2026-01-20 22:43:23.659438 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.032)       0:01:17.875 *******
2026-01-20 22:43:23.659465 | controller | skipping: [instance]
2026-01-20 22:43:23.734250 | controller |
2026-01-20 22:43:23.734285 | controller | TASK [reproducer : Generate libvirt_manager_bm_info_data fact] *****************
2026-01-20 22:43:23.734293 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.024)       0:01:17.899 *******
2026-01-20 22:43:23.734304 | controller | ok: [instance] => (item={'key': 'cifmw-compute-0', 'value': '20f8929e-571d-583f-969c-f0d6357022c1'})
2026-01-20 22:43:24.143366 | controller | ok: [instance] => (item={'key': 'cifmw-compute-1', 'value': 'f40ec783-79a5-5186-b9a6-30fad0c33e27'})
2026-01-20 22:43:24.143398 | controller |
2026-01-20 22:43:24.143406 | controller | TASK [reproducer : Output baremetal info file] *********************************
2026-01-20 22:43:24.143412 | controller | Tuesday 20 January 2026  22:43:23 +0000 (0:00:00.074)       0:01:17.974 *******
2026-01-20 22:43:24.143422 | controller | changed: [instance]
2026-01-20 22:43:24.168620 | controller |
2026-01-20 22:43:24.168649 | controller | TASK [reproducer : Output ironic_nodes to file] ********************************
2026-01-20 22:43:24.168667 | controller | Tuesday 20 January 2026  22:43:24 +0000 (0:00:00.409)       0:01:18.383 *******
2026-01-20 22:43:24.168678 | controller | skipping: [instance]
2026-01-20 22:43:24.241241 | controller |
2026-01-20 22:43:24.241267 | controller | TASK [Run Sushy Emulator role against OCP] *************************************
2026-01-20 22:43:24.241275 | controller | Tuesday 20 January 2026  22:43:24 +0000 (0:00:00.025)       0:01:18.408 *******
2026-01-20 22:43:24.241284 | controller |
2026-01-20 22:43:24.474273 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] ***************
2026-01-20 22:43:24.474307 | controller | Tuesday 20 January 2026  22:43:24 +0000 (0:00:00.072)       0:01:18.481 *******
2026-01-20 22:43:24.474320 | controller | changed: [instance]
2026-01-20 22:43:28.472449 | controller |
2026-01-20 22:43:28.472500 | controller | TASK [sushy_emulator : Install required packages] ******************************
2026-01-20 22:43:28.472509 | controller | Tuesday 20 January 2026  22:43:24 +0000 (0:00:00.232)       0:01:18.714 *******
2026-01-20 22:43:28.472523 | controller | changed: [instance]
2026-01-20 22:43:29.185818 | controller |
2026-01-20 22:43:29.185855 | controller | TASK [sushy_emulator : Get ingresses domain] ***********************************
2026-01-20 22:43:29.185863 | controller | Tuesday 20 January 2026  22:43:28 +0000 (0:00:03.998)       0:01:22.712 *******
2026-01-20 22:43:29.185873 | controller | changed: [instance]
2026-01-20 22:43:29.212188 | controller |
2026-01-20 22:43:29.212221 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] *********************
2026-01-20 22:43:29.212230 | controller | Tuesday 20 January 2026  22:43:29 +0000 (0:00:00.713)       0:01:23.425 *******
2026-01-20 22:43:29.212240 | controller | ok: [instance]
2026-01-20 22:43:29.502943 | controller |
2026-01-20 22:43:29.502979 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] **********************
2026-01-20 22:43:29.502988 | controller | Tuesday 20 January 2026  22:43:29 +0000 (0:00:00.026)       0:01:23.451 *******
2026-01-20 22:43:29.502998 | controller | changed: [instance]
2026-01-20 22:43:29.757682 | controller |
2026-01-20 22:43:29.757714 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ********************
2026-01-20 22:43:29.757722 | controller | Tuesday 20 January 2026  22:43:29 +0000 (0:00:00.290)       0:01:23.742 *******
2026-01-20 22:43:29.757732 | controller | ok: [instance]
2026-01-20 22:43:31.266226 | controller |
2026-01-20 22:43:31.266327 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] *******************************
2026-01-20 22:43:31.266337 | controller | Tuesday 20 January 2026  22:43:29 +0000 (0:00:00.255)       0:01:23.997 *******
2026-01-20 22:43:31.266348 | controller | changed: [instance -> controller-0(192.168.26.197)]
2026-01-20 22:43:31.568200 | controller |
2026-01-20 22:43:31.568238 | controller | TASK [sushy_emulator : Run ssh-keyscan] ****************************************
2026-01-20 22:43:31.568247 | controller | Tuesday 20 January 2026  22:43:31 +0000 (0:00:01.507)       0:01:25.504 *******
2026-01-20 22:43:31.568257 | controller | changed: [instance]
2026-01-20 22:43:31.952788 | controller |
2026-01-20 22:43:31.952825 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************
2026-01-20 22:43:31.952834 | controller | Tuesday 20 January 2026  22:43:31 +0000 (0:00:00.303)       0:01:25.807 *******
2026-01-20 22:43:31.952847 | controller | changed: [instance]
2026-01-20 22:43:31.953295 | controller |
2026-01-20 22:43:31.986071 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2026-01-20 22:43:31.986099 | controller | Tuesday 20 January 2026  22:43:31 +0000 (0:00:00.384)       0:01:26.192 *******
2026-01-20 22:43:31.986111 | controller | skipping: [instance]
2026-01-20 22:43:32.018623 | controller |
2026-01-20 22:43:32.018646 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2026-01-20 22:43:32.018654 | controller | Tuesday 20 January 2026  22:43:31 +0000 (0:00:00.033)       0:01:26.226 *******
2026-01-20 22:43:32.018663 | controller | skipping: [instance]
2026-01-20 22:43:32.019024 | controller |
2026-01-20 22:43:32.049879 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2026-01-20 22:43:32.049905 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.032)       0:01:26.258 *******
2026-01-20 22:43:32.049923 | controller | skipping: [instance]
2026-01-20 22:43:32.093786 | controller |
2026-01-20 22:43:32.093817 | controller | TASK [sushy_emulator : Generate list of filtered VMs] **************************
2026-01-20 22:43:32.093826 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.030)       0:01:26.289 *******
2026-01-20 22:43:32.093836 | controller | ok: [instance]
2026-01-20 22:43:32.121194 | controller |
2026-01-20 22:43:32.121220 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] ***************************
2026-01-20 22:43:32.121234 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.043)       0:01:26.333 *******
2026-01-20 22:43:32.121253 | controller | skipping: [instance]
2026-01-20 22:43:32.145623 | controller |
2026-01-20 22:43:32.145652 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ********
2026-01-20 22:43:32.145664 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.027)       0:01:26.360 *******
2026-01-20 22:43:32.145674 | controller | skipping: [instance]
2026-01-20 22:43:32.145899 | controller |
2026-01-20 22:43:32.145919 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] ***************
2026-01-20 22:43:32.145929 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.024)       0:01:26.385 *******
2026-01-20 22:43:32.170001 | controller | skipping: [instance]
2026-01-20 22:43:32.399666 | controller |
2026-01-20 22:43:32.399697 | controller | TASK [sushy_emulator : Generate htpasswd string] *******************************
2026-01-20 22:43:32.399705 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.024)       0:01:26.409 *******
2026-01-20 22:43:32.399715 | controller | changed: [instance]
2026-01-20 22:43:34.353271 | controller |
2026-01-20 22:43:34.353304 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] *********************
2026-01-20 22:43:34.353317 | controller | Tuesday 20 January 2026  22:43:32 +0000 (0:00:00.229)       0:01:26.639 *******
2026-01-20 22:43:34.353327 | controller | changed: [instance] => (item=secret)
2026-01-20 22:43:34.375529 | controller | changed: [instance] => (item=configmap)
2026-01-20 22:43:34.375573 | controller | changed: [instance] => (item=pod)
2026-01-20 22:43:34.375584 | controller | changed: [instance] => (item=service)
2026-01-20 22:43:34.375590 | controller | changed: [instance] => (item=route)
2026-01-20 22:43:34.375596 | controller |
2026-01-20 22:43:34.375601 | controller | TASK [sushy_emulator : Write sushy emulator config] ****************************
2026-01-20 22:43:34.375611 | controller | Tuesday 20 January 2026  22:43:34 +0000 (0:00:01.953)       0:01:28.592 *******
2026-01-20 22:43:34.375622 | controller | skipping: [instance]
2026-01-20 22:43:34.400734 | controller |
2026-01-20 22:43:34.400764 | controller | TASK [sushy_emulator : Write htpasswd string to file] **************************
2026-01-20 22:43:34.400772 | controller | Tuesday 20 January 2026  22:43:34 +0000 (0:00:00.023)       0:01:28.615 *******
2026-01-20 22:43:34.400789 | controller | skipping: [instance]
2026-01-20 22:43:35.584230 | controller |
2026-01-20 22:43:35.584273 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ********************
2026-01-20 22:43:35.584282 | controller | Tuesday 20 January 2026  22:43:34 +0000 (0:00:00.025)       0:01:28.640 *******
2026-01-20 22:43:35.584293 | controller | changed: [instance]
2026-01-20 22:44:36.704406 | controller |
2026-01-20 22:44:36.704453 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] ***
2026-01-20 22:44:36.704462 | controller | Tuesday 20 January 2026  22:43:35 +0000 (0:00:01.178)       0:01:29.818 *******
2026-01-20 22:44:36.704473 | controller | ok: [instance]
2026-01-20 22:44:40.246643 | controller |
2026-01-20 22:44:40.246692 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] *************************
2026-01-20 22:44:40.246702 | controller | Tuesday 20 January 2026  22:44:36 +0000 (0:01:01.124)       0:02:30.943 *******
2026-01-20 22:44:40.246714 | controller | changed: [instance] => (item=secret)
2026-01-20 22:45:57.134648 | controller | changed: [instance] => (item=configmap)
2026-01-20 22:45:57.134713 | controller | changed: [instance] => (item=service)
2026-01-20 22:45:57.134721 | controller | changed: [instance] => (item=route)
2026-01-20 22:45:57.134727 | controller |
2026-01-20 22:45:57.134733 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] **********************
2026-01-20 22:45:57.134739 | controller | Tuesday 20 January 2026  22:44:40 +0000 (0:00:03.541)       0:02:34.485 *******
2026-01-20 22:45:57.134754 | controller | [WARNING]: unknown field "spec.selector"
2026-01-20 22:45:57.135451 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.135916 | controller | "spec.containers[0].readinessProbe.httpGet.initialDelaySeconds"
2026-01-20 22:45:57.135937 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.136357 | controller | "spec.containers[0].readinessProbe.httpGet.periodSeconds"
2026-01-20 22:45:57.136374 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.136799 | controller | "spec.containers[0].livenessProbe.httpGet.initialDelaySeconds"
2026-01-20 22:45:57.136817 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.137243 | controller | "spec.containers[0].livenessProbe.httpGet.failureThreshold"
2026-01-20 22:45:57.137259 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.137679 | controller | "spec.containers[0].livenessProbe.httpGet.periodSeconds"
2026-01-20 22:45:57.137698 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.138099 | controller | "spec.containers[0].startupProbe.httpGet.failureThreshold"
2026-01-20 22:45:57.138115 | controller | [WARNING]: unknown field
2026-01-20 22:45:57.147357 | controller | "spec.containers[0].startupProbe.httpGet.initialDelaySeconds"
2026-01-20 22:45:57.147410 | controller | changed: [instance]
2026-01-20 22:45:57.147431 | controller |
2026-01-20 22:45:57.147437 | controller | TASK [podman : Ensure podman is installed] *************************************
2026-01-20 22:45:57.147445 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:01:16.901)       0:03:51.387 *******
2026-01-20 22:45:57.167874 | controller | skipping: [instance]
2026-01-20 22:45:57.167936 | controller |
2026-01-20 22:45:57.168047 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2026-01-20 22:45:57.168166 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.020)       0:03:51.408 *******
2026-01-20 22:45:57.193600 | controller | skipping: [instance]
2026-01-20 22:45:57.193659 | controller |
2026-01-20 22:45:57.193770 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2026-01-20 22:45:57.193878 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.025)       0:03:51.434 *******
2026-01-20 22:45:57.218105 | controller | skipping: [instance]
2026-01-20 22:45:57.218282 | controller |
2026-01-20 22:45:57.218325 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2026-01-20 22:45:57.218428 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.024)       0:03:51.458 *******
2026-01-20 22:45:57.238876 | controller | skipping: [instance]
2026-01-20 22:45:57.238961 | controller |
2026-01-20 22:45:57.239084 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2026-01-20 22:45:57.239182 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.021)       0:03:51.479 *******
2026-01-20 22:45:57.264728 | controller | skipping: [instance]
2026-01-20 22:45:57.264816 | controller |
2026-01-20 22:45:57.264910 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ********************
2026-01-20 22:45:57.265023 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.025)       0:03:51.505 *******
2026-01-20 22:45:57.285447 | controller | skipping: [instance]
2026-01-20 22:45:57.285536 | controller |
2026-01-20 22:45:57.285686 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] **************
2026-01-20 22:45:57.285806 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.020)       0:03:51.525 *******
2026-01-20 22:45:57.309728 | controller | skipping: [instance]
2026-01-20 22:45:57.309833 | controller |
2026-01-20 22:45:57.309957 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] *******************
2026-01-20 22:45:57.310085 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.024)       0:03:51.550 *******
2026-01-20 22:45:57.368839 | controller |
2026-01-20 22:45:57.368921 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] ***
2026-01-20 22:45:57.369041 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.059)       0:03:51.609 *******
2026-01-20 22:45:57.398727 | controller | ok: [instance]
2026-01-20 22:45:57.398816 | controller |
2026-01-20 22:45:57.398943 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2026-01-20 22:45:57.399071 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.029)       0:03:51.639 *******
2026-01-20 22:45:57.424833 | controller | skipping: [instance]
2026-01-20 22:45:57.424920 | controller |
2026-01-20 22:45:57.425032 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2026-01-20 22:45:57.425145 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.026)       0:03:51.665 *******
2026-01-20 22:45:57.449592 | controller | skipping: [instance]
2026-01-20 22:45:57.449666 | controller |
2026-01-20 22:45:57.449773 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] ***
2026-01-20 22:45:57.449879 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.024)       0:03:51.690 *******
2026-01-20 22:45:57.920388 | controller | fatal: [instance]: FAILED! => changed=false
2026-01-20 22:45:57.920455 | controller |   cache_control: private, max-age=0, no-cache, no-store
2026-01-20 22:45:57.920465 | controller |   content: |-
2026-01-20 22:45:57.920603 | controller |     <html>
2026-01-20 22:45:57.920634 | controller |       <head>
2026-01-20 22:45:57.920761 | controller |         <meta name="viewport" content="width=device-width, initial-scale=1">
2026-01-20 22:45:57.920849 | controller |
2026-01-20 22:45:57.920941 | controller |         <style type="text/css">
2026-01-20 22:45:57.921039 | controller |           body {
2026-01-20 22:45:57.921153 | controller |             font-family: "Helvetica Neue", Helvetica, Arial, sans-serif;
2026-01-20 22:45:57.921258 | controller |             line-height: 1.66666667;
2026-01-20 22:45:57.921394 | controller |             font-size: 16px;
2026-01-20 22:45:57.921415 | controller |             color: #333;
2026-01-20 22:45:57.921556 | controller |             background-color: #fff;
2026-01-20 22:45:57.921611 | controller |             margin: 2em 1em;
2026-01-20 22:45:57.921705 | controller |           }
2026-01-20 22:45:57.921794 | controller |           h1 {
2026-01-20 22:45:57.921884 | controller |             font-size: 28px;
2026-01-20 22:45:57.921974 | controller |             font-weight: 400;
2026-01-20 22:45:57.922071 | controller |           }
2026-01-20 22:45:57.922162 | controller |           p {
2026-01-20 22:45:57.922305 | controller |             margin: 0 0 10px;
2026-01-20 22:45:57.922368 | controller |           }
2026-01-20 22:45:57.922439 | controller |           .alert.alert-info {
2026-01-20 22:45:57.922531 | controller |             background-color: #F0F0F0;
2026-01-20 22:45:57.922660 | controller |             margin-top: 30px;
2026-01-20 22:45:57.922739 | controller |             padding: 30px;
2026-01-20 22:45:57.922850 | controller |           }
2026-01-20 22:45:57.922913 | controller |           .alert p {
2026-01-20 22:45:57.923002 | controller |             padding-left: 35px;
2026-01-20 22:45:57.923102 | controller |           }
2026-01-20 22:45:57.923190 | controller |           ul {
2026-01-20 22:45:57.923277 | controller |             padding-left: 51px;
2026-01-20 22:45:57.923365 | controller |             position: relative;
2026-01-20 22:45:57.923485 | controller |           }
2026-01-20 22:45:57.923552 | controller |           li {
2026-01-20 22:45:57.923664 | controller |             font-size: 14px;
2026-01-20 22:45:57.923757 | controller |             margin-bottom: 1em;
2026-01-20 22:45:57.923841 | controller |           }
2026-01-20 22:45:57.923929 | controller |           p.info {
2026-01-20 22:45:57.924021 | controller |             position: relative;
2026-01-20 22:45:57.924126 | controller |             font-size: 20px;
2026-01-20 22:45:57.924207 | controller |           }
2026-01-20 22:45:57.924301 | controller |           p.info:before, p.info:after {
2026-01-20 22:45:57.924388 | controller |             content: "";
2026-01-20 22:45:57.924480 | controller |             left: 0;
2026-01-20 22:45:57.924580 | controller |             position: absolute;
2026-01-20 22:45:57.924677 | controller |             top: 0;
2026-01-20 22:45:57.924769 | controller |           }
2026-01-20 22:45:57.924853 | controller |           p.info:before {
2026-01-20 22:45:57.924937 | controller |             background: #0066CC;
2026-01-20 22:45:57.925035 | controller |             border-radius: 16px;
2026-01-20 22:45:57.925137 | controller |             color: #fff;
2026-01-20 22:45:57.925220 | controller |             content: "i";
2026-01-20 22:45:57.925312 | controller |             font: bold 16px/24px serif;
2026-01-20 22:45:57.925397 | controller |             height: 24px;
2026-01-20 22:45:57.925493 | controller |             left: 0px;
2026-01-20 22:45:57.925596 | controller |             text-align: center;
2026-01-20 22:45:57.925689 | controller |             top: 4px;
2026-01-20 22:45:57.925777 | controller |             width: 24px;
2026-01-20 22:45:57.925863 | controller |           }
2026-01-20 22:45:57.925950 | controller |
2026-01-20 22:45:57.926037 | controller |           @media (min-width: 768px) {
2026-01-20 22:45:57.926141 | controller |             body {
2026-01-20 22:45:57.926228 | controller |               margin: 6em;
2026-01-20 22:45:57.926317 | controller |             }
2026-01-20 22:45:57.926405 | controller |           }
2026-01-20 22:45:57.926490 | controller |         </style>
2026-01-20 22:45:57.926592 | controller |       </head>
2026-01-20 22:45:57.926684 | controller |       <body>
2026-01-20 22:45:57.926772 | controller |         <div>
2026-01-20 22:45:57.926859 | controller |           <h1>Application is not available</h1>
2026-01-20 22:45:57.926957 | controller |           <p>The application is currently not serving requests at this endpoint. It may not have been started or is still starting.</p>
2026-01-20 22:45:57.927042 | controller |
2026-01-20 22:45:57.927153 | controller |           <div class="alert alert-info">
2026-01-20 22:45:57.927242 | controller |             <p class="info">
2026-01-20 22:45:57.927334 | controller |               Possible reasons you are seeing this page:
2026-01-20 22:45:57.927427 | controller |             </p>
2026-01-20 22:45:57.927513 | controller |             <ul>
2026-01-20 22:45:57.927617 | controller |               <li>
2026-01-20 22:45:57.927710 | controller |                 <strong>The host doesn't exist.</strong>
2026-01-20 22:45:57.927806 | controller |                 Make sure the hostname was typed correctly and that a route matching this hostname exists.
2026-01-20 22:45:57.927917 | controller |               </li>
2026-01-20 22:45:57.928005 | controller |               <li>
2026-01-20 22:45:57.928122 | controller |                 <strong>The host exists, but doesn't have a matching path.</strong>
2026-01-20 22:45:57.928234 | controller |                 Check if the URL path was typed correctly and that the route was created using the desired path.
2026-01-20 22:45:57.928326 | controller |               </li>
2026-01-20 22:45:57.928414 | controller |               <li>
2026-01-20 22:45:57.928503 | controller |                 <strong>Route and path matches, but all pods are down.</strong>
2026-01-20 22:45:57.929283 | controller |                 Make sure that the resources exposed by this route (pods, services, deployment configs, etc) have at least one pod running.
2026-01-20 22:45:57.929303 | controller |               </li>
2026-01-20 22:45:57.929309 | controller |             </ul>
2026-01-20 22:45:57.929318 | controller |           </div>
2026-01-20 22:45:57.929324 | controller |         </div>
2026-01-20 22:45:57.929329 | controller |       </body>
2026-01-20 22:45:57.929334 | controller |     </html>
2026-01-20 22:45:57.929339 | controller |   content_type: text/html
2026-01-20 22:45:57.929346 | controller |   elapsed: 0
2026-01-20 22:45:57.929417 | controller |   msg: 'Status code was 503 and not [200]: HTTP Error 503: Service Unavailable'
2026-01-20 22:45:57.929501 | controller |   pragma: no-cache
2026-01-20 22:45:57.929623 | controller |   redirected: false
2026-01-20 22:45:57.929707 | controller |   status: 503
2026-01-20 22:45:57.929802 | controller |   url: http://sushy-emulator.apps-crc.testing/redfish/v1/Managers
2026-01-20 22:45:57.929970 | controller |
2026-01-20 22:45:57.930074 | controller | PLAY RECAP *********************************************************************
2026-01-20 22:45:57.930189 | controller | instance                   : ok=209  changed=78   unreachable=0    failed=1    skipped=95   rescued=0    ignored=0
2026-01-20 22:45:57.930265 | controller |
2026-01-20 22:45:57.930355 | controller | Tuesday 20 January 2026  22:45:57 +0000 (0:00:00.473)       0:03:52.163 *******
2026-01-20 22:45:57.930437 | controller | ===============================================================================
2026-01-20 22:45:57.930528 | controller | sushy_emulator : Apply Sushy Emulator pod resource --------------------- 76.90s
2026-01-20 22:45:57.930649 | controller | sushy_emulator : Check if router pod is running in openshift-ingress namespace -- 61.12s
2026-01-20 22:45:57.930745 | controller | libvirt_manager : Install packages required for using KVM --------------- 8.67s
2026-01-20 22:45:57.930836 | controller | ci_nmstate : Install required packages on instance ---------------------- 5.01s
2026-01-20 22:45:57.930927 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 4.86s
2026-01-20 22:45:57.931018 | controller | sushy_emulator : Install required packages ------------------------------ 4.00s
2026-01-20 22:45:57.931123 | controller | sushy_emulator : Apply Sushy Emulator resources ------------------------- 3.54s
2026-01-20 22:45:57.931219 | controller | ci_nmstate : Apply the desidered state on instance ---------------------- 2.10s
2026-01-20 22:45:57.931308 | controller | sushy_emulator : Write sushy emulator resource loop --------------------- 1.95s
2026-01-20 22:45:57.931398 | controller | libvirt_manager : Restart firewalld ------------------------------------- 1.89s
2026-01-20 22:45:57.931503 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.51s
2026-01-20 22:45:57.931608 | controller | dnsmasq : Add/Remove address -------------------------------------------- 1.49s
2026-01-20 22:45:57.931703 | controller | dnsmasq : Install needed packages --------------------------------------- 1.46s
2026-01-20 22:45:57.931793 | controller | libvirt_manager : Ensure read-write socket is enabled for storage. ------ 1.40s
2026-01-20 22:45:57.931884 | controller | libvirt_manager : Ensure read-only socket is enabled for network. ------- 1.34s
2026-01-20 22:45:57.931968 | controller | sushy_emulator : Create the sushy-emulator namespace -------------------- 1.18s
2026-01-20 22:45:57.932071 | controller | libvirt_manager : Start VMs for type {{ vm_type }} ---------------------- 1.05s
2026-01-20 22:45:57.932162 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 1.00s
2026-01-20 22:45:57.932252 | controller | Gathering Facts --------------------------------------------------------- 0.90s
2026-01-20 22:45:57.932343 | controller | dnsmasq : Enable and start service -------------------------------------- 0.84s
2026-01-20 22:45:57.989700 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/sushy_emulator/default/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/sushy_emulator/molecule/default/converge.yml']
2026-01-20 22:45:57.990115 | controller | WARNING  An error occurred during the test sequence action: 'converge'. Cleaning up.
2026-01-20 22:45:58.000432 | controller | INFO     Running default > cleanup
2026-01-20 22:45:58.001176 | controller | WARNING  Skipping, cleanup playbook not configured.
2026-01-20 22:45:58.009928 | controller | INFO     Running default > destroy
2026-01-20 22:45:58.010734 | controller | WARNING  Skipping, instances are delegated.
2026-01-20 22:45:58.011191 | controller | INFO     Pruning extra files from scenario ephemeral directory
2026-01-20 22:45:58.013443 | controller | INFO     Writing /tmp/report.html report.
2026-01-20 22:45:58.456938 | [controller] Waiting on logger
2026-01-20 22:46:03.643862 | [controller] Waiting on logger
2026-01-20 22:46:14.076097 | [controller] Waiting on logger
2026-01-20 22:46:23.456320 | [controller] Waiting on logger
2026-01-20 22:46:28.094336 | [Zuul] Log Stream did not terminate
2026-01-20 22:46:28.094584 | controller | ERROR
2026-01-20 22:46:28.094669 | controller | {
2026-01-20 22:46:28.094702 | controller |   "delta": "0:07:59.921053",
2026-01-20 22:46:28.094723 | controller |   "end": "2026-01-20 22:45:58.068892",
2026-01-20 22:46:28.094741 | controller |   "msg": "non-zero return code",
2026-01-20 22:46:28.094756 | controller |   "rc": 1,
2026-01-20 22:46:28.094771 | controller |   "start": "2026-01-20 22:37:58.147839"
2026-01-20 22:46:28.094787 | controller | }
failure
2026-01-20 22:46:28.139919 | 
2026-01-20 22:46:28.139981 | PLAY RECAP
2026-01-20 22:46:28.140022 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2026-01-20 22:46:28.140043 | 
2026-01-20 22:46:28.202993 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2026-01-20 22:46:28.203732 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-01-20 22:46:28.733813 | 
2026-01-20 22:46:28.733907 | PLAY [Run ci/playbooks/collect-logs.yml]
2026-01-20 22:46:28.754071 | 
2026-01-20 22:46:28.754147 | TASK [Filter out host if needed]
2026-01-20 22:46:28.762773 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2026-01-20 22:46:28.767174 | 
2026-01-20 22:46:28.767241 | TASK [Ensure file is present]
2026-01-20 22:46:29.160822 | controller | ok
2026-01-20 22:46:29.166659 | 
2026-01-20 22:46:29.166741 | TASK [Manage molecule report file]
2026-01-20 22:46:29.189505 | [controller] Waiting on logger
2026-01-20 22:46:38.560362 | [controller] Waiting on logger
2026-01-20 22:46:48.955766 | [controller] Waiting on logger
2026-01-20 22:46:59.387905 | [controller] Waiting on logger
2026-01-20 22:46:59.559183 | [Zuul] Log Stream did not terminate
2026-01-20 22:46:59.559345 | controller | changed
2026-01-20 22:46:59.564348 | 
2026-01-20 22:46:59.564410 | TASK [Check if we get ci-framework-data basedir]
2026-01-20 22:46:59.827047 | controller | ok
2026-01-20 22:46:59.832232 | 
2026-01-20 22:46:59.832318 | TASK [Create ci-framework-data log directory for zuul]
2026-01-20 22:47:00.204044 | controller | changed
2026-01-20 22:47:00.209830 | 
2026-01-20 22:47:00.209917 | TASK [Copy ci-framework interesting files]
2026-01-20 22:47:05.236218 | controller | changed
2026-01-20 22:47:05.241757 | 
2026-01-20 22:47:05.241834 | TASK [Get SELinux listing]
2026-01-20 22:47:06.299773 | [controller] Waiting on logger
2026-01-20 22:47:15.643809 | [controller] Waiting on logger
2026-01-20 22:47:26.075825 | [controller] Waiting on logger
2026-01-20 22:47:35.456522 | [controller] Waiting on logger
2026-01-20 22:47:35.515009 | [Zuul] Log Stream did not terminate
2026-01-20 22:47:35.515211 | controller | changed
2026-01-20 22:47:35.521171 | 
2026-01-20 22:47:35.521239 | TASK [Generate log index]
2026-01-20 22:47:36.573082 | controller | changed
2026-01-20 22:47:36.578059 | 
2026-01-20 22:47:36.578136 | TASK [Get some env related data]
2026-01-20 22:47:37.660071 | [controller] Waiting on logger
2026-01-20 22:47:52.682530 | controller | changed
2026-01-20 22:47:52.687677 | 
2026-01-20 22:47:52.687743 | TASK [Generate list of logs to collect in home directory]
2026-01-20 22:47:53.065951 | controller | ok: All paths examined
2026-01-20 22:47:53.071322 | 
2026-01-20 22:47:53.071385 | LOOP [Copy logs from home directory]
2026-01-20 22:47:53.083780 | [controller] Waiting on logger
2026-01-20 22:47:53.636774 | controller | changed:
2026-01-20 22:47:53.636862 | controller | {
2026-01-20 22:47:53.636888 | controller |   "atime": 1743544925.4788878,
2026-01-20 22:47:53.636907 | controller |   "ctime": 1743545329.1409318,
2026-01-20 22:47:53.636924 | controller |   "dev": 64513,
2026-01-20 22:47:53.636940 | controller |   "gid": 1000,
2026-01-20 22:47:53.636954 | controller |   "gr_name": "zuul",
2026-01-20 22:47:53.636968 | controller |   "inode": 4518807,
2026-01-20 22:47:53.636982 | controller |   "isblk": false,
2026-01-20 22:47:53.636996 | controller |   "ischr": false,
2026-01-20 22:47:53.637010 | controller |   "isdir": false,
2026-01-20 22:47:53.637024 | controller |   "isfifo": false,
2026-01-20 22:47:53.637038 | controller |   "isgid": false,
2026-01-20 22:47:53.637052 | controller |   "islnk": false,
2026-01-20 22:47:53.637066 | controller |   "isreg": true,
2026-01-20 22:47:53.637080 | controller |   "issock": false,
2026-01-20 22:47:53.637094 | controller |   "isuid": false,
2026-01-20 22:47:53.637108 | controller |   "mode": "0644",
2026-01-20 22:47:53.637121 | controller |   "mtime": 1743545329.1409318,
2026-01-20 22:47:53.637138 | controller |   "nlink": 1,
2026-01-20 22:47:53.637153 | controller |   "path": "/home/zuul/crc-setup.log",
2026-01-20 22:47:53.637167 | controller |   "pw_name": "zuul",
2026-01-20 22:47:53.637181 | controller |   "rgrp": true,
2026-01-20 22:47:53.637196 | controller |   "roth": true,
2026-01-20 22:47:53.637210 | controller |   "rusr": true,
2026-01-20 22:47:53.637223 | controller |   "size": 4108,
2026-01-20 22:47:53.637237 | controller |   "uid": 1000,
2026-01-20 22:47:53.637251 | controller |   "wgrp": false,
2026-01-20 22:47:53.637265 | controller |   "woth": false,
2026-01-20 22:47:53.637278 | controller |   "wusr": true,
2026-01-20 22:47:53.637291 | controller |   "xgrp": false,
2026-01-20 22:47:53.637378 | controller |   "xoth": false,
2026-01-20 22:47:53.637400 | controller |   "xusr": false
2026-01-20 22:47:53.637416 | controller | }
2026-01-20 22:47:54.149603 | controller | changed:
2026-01-20 22:47:54.149673 | controller | {
2026-01-20 22:47:54.149697 | controller |   "atime": 1743545331.0429637,
2026-01-20 22:47:54.149715 | controller |   "ctime": 1743545842.0111232,
2026-01-20 22:47:54.149731 | controller |   "dev": 64513,
2026-01-20 22:47:54.149747 | controller |   "gid": 1000,
2026-01-20 22:47:54.149762 | controller |   "gr_name": "zuul",
2026-01-20 22:47:54.149776 | controller |   "inode": 4194437,
2026-01-20 22:47:54.149790 | controller |   "isblk": false,
2026-01-20 22:47:54.149804 | controller |   "ischr": false,
2026-01-20 22:47:54.149819 | controller |   "isdir": false,
2026-01-20 22:47:54.149834 | controller |   "isfifo": false,
2026-01-20 22:47:54.149849 | controller |   "isgid": false,
2026-01-20 22:47:54.149864 | controller |   "islnk": false,
2026-01-20 22:47:54.149879 | controller |   "isreg": true,
2026-01-20 22:47:54.149894 | controller |   "issock": false,
2026-01-20 22:47:54.149908 | controller |   "isuid": false,
2026-01-20 22:47:54.149922 | controller |   "mode": "0644",
2026-01-20 22:47:54.149935 | controller |   "mtime": 1743545842.0111232,
2026-01-20 22:47:54.149955 | controller |   "nlink": 1,
2026-01-20 22:47:54.149969 | controller |   "path": "/home/zuul/crc-start.log",
2026-01-20 22:47:54.149983 | controller |   "pw_name": "zuul",
2026-01-20 22:47:54.149998 | controller |   "rgrp": true,
2026-01-20 22:47:54.150012 | controller |   "roth": true,
2026-01-20 22:47:54.150026 | controller |   "rusr": true,
2026-01-20 22:47:54.150040 | controller |   "size": 4023,
2026-01-20 22:47:54.150054 | controller |   "uid": 1000,
2026-01-20 22:47:54.150067 | controller |   "wgrp": false,
2026-01-20 22:47:54.150080 | controller |   "woth": false,
2026-01-20 22:47:54.150093 | controller |   "wusr": true,
2026-01-20 22:47:54.150107 | controller |   "xgrp": false,
2026-01-20 22:47:54.150120 | controller |   "xoth": false,
2026-01-20 22:47:54.150134 | controller |   "xusr": false
2026-01-20 22:47:54.150147 | controller | }
2026-01-20 22:47:54.666246 | controller | changed:
2026-01-20 22:47:54.666318 | controller | {
2026-01-20 22:47:54.666349 | controller |   "atime": 1768948659.8684037,
2026-01-20 22:47:54.666370 | controller |   "ctime": 1768948675.6900446,
2026-01-20 22:47:54.666388 | controller |   "dev": 64513,
2026-01-20 22:47:54.666404 | controller |   "gid": 1000,
2026-01-20 22:47:54.666419 | controller |   "gr_name": "zuul",
2026-01-20 22:47:54.666434 | controller |   "inode": 4638646,
2026-01-20 22:47:54.666448 | controller |   "isblk": false,
2026-01-20 22:47:54.666462 | controller |   "ischr": false,
2026-01-20 22:47:54.666476 | controller |   "isdir": false,
2026-01-20 22:47:54.666490 | controller |   "isfifo": false,
2026-01-20 22:47:54.666505 | controller |   "isgid": false,
2026-01-20 22:47:54.666519 | controller |   "islnk": false,
2026-01-20 22:47:54.666535 | controller |   "isreg": true,
2026-01-20 22:47:54.666550 | controller |   "issock": false,
2026-01-20 22:47:54.666565 | controller |   "isuid": false,
2026-01-20 22:47:54.666578 | controller |   "mode": "0644",
2026-01-20 22:47:54.666602 | controller |   "mtime": 1768948675.6900446,
2026-01-20 22:47:54.666618 | controller |   "nlink": 1,
2026-01-20 22:47:54.666632 | controller |   "path": "/home/zuul/ansible.log",
2026-01-20 22:47:54.666645 | controller |   "pw_name": "zuul",
2026-01-20 22:47:54.666658 | controller |   "rgrp": true,
2026-01-20 22:47:54.666671 | controller |   "roth": true,
2026-01-20 22:47:54.666684 | controller |   "rusr": true,
2026-01-20 22:47:54.666697 | controller |   "size": 6749,
2026-01-20 22:47:54.666710 | controller |   "uid": 1000,
2026-01-20 22:47:54.666723 | controller |   "wgrp": false,
2026-01-20 22:47:54.666736 | controller |   "woth": false,
2026-01-20 22:47:54.666750 | controller |   "wusr": true,
2026-01-20 22:47:54.666763 | controller |   "xgrp": false,
2026-01-20 22:47:54.666776 | controller |   "xoth": false,
2026-01-20 22:47:54.666789 | controller |   "xusr": false
2026-01-20 22:47:54.666804 | controller | }
2026-01-20 22:47:54.674902 | 
2026-01-20 22:47:54.675006 | TASK [Copy crio stats log file]
2026-01-20 22:47:54.688390 | controller | skipping: Conditional result was False
2026-01-20 22:47:54.693626 | 
2026-01-20 22:47:54.693688 | TASK [Get SELinux related data]
2026-01-20 22:47:54.716423 | [controller] Waiting on logger
2026-01-20 22:48:05.115869 | [controller] Waiting on logger
2026-01-20 22:48:14.496763 | [controller] Waiting on logger
2026-01-20 22:48:24.892172 | [controller] Waiting on logger
2026-01-20 22:48:24.984822 | [Zuul] Log Stream did not terminate
2026-01-20 22:48:24.985056 | controller | ERROR
2026-01-20 22:48:24.985159 | controller | {
2026-01-20 22:48:24.985190 | controller |   "delta": "0:00:00.010505",
2026-01-20 22:48:24.985213 | controller |   "end": "2026-01-20 22:47:54.963297",
2026-01-20 22:48:24.985231 | controller |   "msg": "non-zero return code",
2026-01-20 22:48:24.985248 | controller |   "rc": 1,
2026-01-20 22:48:24.985265 | controller |   "start": "2026-01-20 22:47:54.952792"
2026-01-20 22:48:24.985282 | controller | }
2026-01-20 22:48:24.985329 | controller | ERROR: Ignoring Errors
2026-01-20 22:48:24.990376 | 
2026-01-20 22:48:24.990442 | TASK [Create system configuration directory]
2026-01-20 22:48:25.231947 | controller | changed
2026-01-20 22:48:25.236675 | 
2026-01-20 22:48:25.236741 | TASK [Get some of the system configurations]
2026-01-20 22:48:28.348110 | [controller] Waiting on logger
2026-01-20 22:48:37.691802 | [controller] Waiting on logger
2026-01-20 22:48:48.123937 | [controller] Waiting on logger
2026-01-20 22:48:55.528486 | [Zuul] Log Stream did not terminate
2026-01-20 22:48:55.528711 | controller | changed
2026-01-20 22:48:55.533943 | 
2026-01-20 22:48:55.534004 | TASK [Copy generated documentation if available]
2026-01-20 22:48:55.547040 | controller | skipping: Conditional result was False
2026-01-20 22:48:55.552816 | 
2026-01-20 22:48:55.552885 | TASK [Copy generated AsciiDoc documentation if available]
2026-01-20 22:48:55.566118 | controller | skipping: Conditional result was False
2026-01-20 22:48:55.570953 | 
2026-01-20 22:48:55.571011 | TASK [Compress logs bigger than 2MB]
2026-01-20 22:48:55.594813 | [controller] Waiting on logger
2026-01-20 22:49:05.979903 | [controller] Waiting on logger
2026-01-20 22:49:16.411907 | [controller] Waiting on logger
2026-01-20 22:49:25.755895 | [controller] Waiting on logger
2026-01-20 22:49:25.853478 | [Zuul] Log Stream did not terminate
2026-01-20 22:49:25.853721 | controller | changed
2026-01-20 22:49:25.859081 | 
2026-01-20 22:49:25.859153 | TASK [Copy files from workspace on node]
2026-01-20 22:49:25.877111 | controller | ok
2026-01-20 22:49:25.898517 | 
2026-01-20 22:49:25.898586 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-20 22:49:25.923479 | controller | skipping: Conditional result was False
2026-01-20 22:49:25.928407 | 
2026-01-20 22:49:25.928472 | TASK [fetch-output : Set log path for single node]
2026-01-20 22:49:25.956688 | controller | ok
2026-01-20 22:49:25.961481 | 
2026-01-20 22:49:25.961544 | LOOP [fetch-output : Ensure local output dirs]
2026-01-20 22:49:26.150974 | controller -> localhost | ok: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/logs"
2026-01-20 22:49:26.151206 | controller -> localhost | changed: All items complete
2026-01-20 22:49:26.151236 | 
2026-01-20 22:49:26.324786 | controller -> localhost | changed: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/artifacts"
2026-01-20 22:49:26.494805 | controller -> localhost | changed: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/docs"
2026-01-20 22:49:26.508350 | 
2026-01-20 22:49:26.508453 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-20 22:49:27.113633 | controller | changed:
2026-01-20 22:49:27.113807 | controller | .d..t...... ./
2026-01-20 22:49:27.113837 | controller | >f+++++++++ README.html
2026-01-20 22:49:27.113858 | controller | >f+++++++++ ansible-execution.log
2026-01-20 22:49:27.113878 | controller | >f+++++++++ ansible.log
2026-01-20 22:49:27.113896 | controller | >f+++++++++ crc-setup.log
2026-01-20 22:49:27.113913 | controller | >f+++++++++ crc-start.log
2026-01-20 22:49:27.113929 | controller | >f+++++++++ dmesg.log
2026-01-20 22:49:27.113945 | controller | >f+++++++++ installed-pkgs.log
2026-01-20 22:49:27.113960 | controller | >f+++++++++ python.log
2026-01-20 22:49:27.113975 | controller | >f+++++++++ registries.conf
2026-01-20 22:49:27.113990 | controller | >f+++++++++ report.html
2026-01-20 22:49:27.114005 | controller | >f+++++++++ selinux-denials.log
2026-01-20 22:49:27.114021 | controller | >f+++++++++ selinux-listing.log
2026-01-20 22:49:27.114036 | controller | cd+++++++++ ci-framework-data/
2026-01-20 22:49:27.114052 | controller | cd+++++++++ ci-framework-data/artifacts/
2026-01-20 22:49:27.114067 | controller | >f+++++++++ ci-framework-data/artifacts/debug_cifmw_libvirt_manager_layout.yml
2026-01-20 22:49:27.114082 | controller | >f+++++++++ ci-framework-data/artifacts/debug_network_data.yml
2026-01-20 22:49:27.114097 | controller | >f+++++++++ ci-framework-data/artifacts/debug_pub_net_value.txt
2026-01-20 22:49:27.114112 | controller | >f+++++++++ ci-framework-data/artifacts/interfaces-info.yml
2026-01-20 22:49:27.114132 | controller | >f+++++++++ ci-framework-data/artifacts/libvirt-uuids.yml
2026-01-20 22:49:27.114148 | controller | >f+++++++++ ci-framework-data/artifacts/net-map-def-patch.yml
2026-01-20 22:49:27.114163 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2026-01-20 22:49:27.114177 | controller | cd+++++++++ ci-framework-data/artifacts/nmstate/
2026-01-20 22:49:27.114192 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-final-state.yaml
2026-01-20 22:49:27.114207 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-state.yaml
2026-01-20 22:49:27.114222 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2026-01-20 22:49:27.114236 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2026-01-20 22:49:27.114251 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2026-01-20 22:49:27.114264 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2026-01-20 22:49:27.114279 | controller | cd+++++++++ ci-framework-data/artifacts/sushy_emulator/
2026-01-20 22:49:27.117030 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/configmap.yaml
2026-01-20 22:49:27.117081 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/known_hosts
2026-01-20 22:49:27.117107 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/pod.yaml
2026-01-20 22:49:27.117128 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/route.yaml
2026-01-20 22:49:27.117145 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/secret.yaml
2026-01-20 22:49:27.117162 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/service.yaml
2026-01-20 22:49:27.117180 | controller | cd+++++++++ ci-framework-data/logs/
2026-01-20 22:49:27.117196 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2026-01-20 22:49:27.117212 | controller | cd+++++++++ registries.conf.d/
2026-01-20 22:49:27.117227 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2026-01-20 22:49:27.117242 | controller | cd+++++++++ system-config/
2026-01-20 22:49:27.117257 | controller | cd+++++++++ system-config/libvirt/
2026-01-20 22:49:27.117272 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2026-01-20 22:49:27.117287 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2026-01-20 22:49:27.117323 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2026-01-20 22:49:27.117344 | controller | >f+++++++++ system-config/libvirt/network.conf
2026-01-20 22:49:27.117361 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2026-01-20 22:49:27.117379 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2026-01-20 22:49:27.117397 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2026-01-20 22:49:27.117413 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2026-01-20 22:49:27.117430 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2026-01-20 22:49:27.117445 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2026-01-20 22:49:27.117461 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2026-01-20 22:49:27.117476 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2026-01-20 22:49:27.117492 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2026-01-20 22:49:27.117507 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2026-01-20 22:49:27.117522 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2026-01-20 22:49:27.117537 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2026-01-20 22:49:27.570925 | controller | changed: .d..t...... ./
2026-01-20 22:49:28.009709 | controller | changed: .d..t...... ./
2026-01-20 22:49:28.022228 | 
2026-01-20 22:49:28.022348 | TASK [Return artifact to Zuul]
2026-01-20 22:49:28.051137 | controller | ok
2026-01-20 22:49:28.069116 | 
2026-01-20 22:49:28.069171 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2026-01-20 22:49:28.069270 | 
2026-01-20 22:49:28.069314 | PLAY RECAP
2026-01-20 22:49:28.069358 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2026-01-20 22:49:28.069381 | 
2026-01-20 22:49:28.146278 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2026-01-20 22:49:28.146981 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-01-20 22:49:28.645473 | 
2026-01-20 22:49:28.645568 | PLAY [all]
2026-01-20 22:49:28.663391 | 
2026-01-20 22:49:28.663465 | TASK [include_role : fetch-output]
2026-01-20 22:49:28.691500 | controller | ok
2026-01-20 22:49:28.707383 | 
2026-01-20 22:49:28.707467 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-20 22:49:28.741491 | controller | skipping: Conditional result was False
2026-01-20 22:49:28.746999 | 
2026-01-20 22:49:28.747077 | TASK [fetch-output : Set log path for single node]
2026-01-20 22:49:28.774621 | controller | ok
2026-01-20 22:49:28.779406 | 
2026-01-20 22:49:28.779478 | LOOP [fetch-output : Ensure local output dirs]
2026-01-20 22:49:29.085387 | controller -> localhost | ok: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/logs"
2026-01-20 22:49:29.264731 | controller -> localhost | ok: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/artifacts"
2026-01-20 22:49:29.446710 | controller -> localhost | ok: "/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/docs"
2026-01-20 22:49:29.456879 | 
2026-01-20 22:49:29.456973 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-20 22:49:30.031111 | controller | ok
2026-01-20 22:49:30.031369 | controller | ok: All items complete
2026-01-20 22:49:30.031408 | 
2026-01-20 22:49:30.481166 | controller | ok
2026-01-20 22:49:30.919373 | controller | ok
2026-01-20 22:49:30.940118 | 
2026-01-20 22:49:30.940229 | TASK [include_role : fetch-output-openshift]
2026-01-20 22:49:30.953975 | controller | skipping: Conditional result was False
2026-01-20 22:49:30.959501 | 
2026-01-20 22:49:30.959572 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-20 22:49:31.286745 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006724
2026-01-20 22:49:31.472592 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006364
2026-01-20 22:49:31.503180 | 
2026-01-20 22:49:31.503262 | PLAY [all]
2026-01-20 22:49:31.517014 | 
2026-01-20 22:49:31.517080 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2026-01-20 22:49:31.971661 | controller | changed
2026-01-20 22:49:31.992592 | 
2026-01-20 22:49:31.992643 | PLAY RECAP
2026-01-20 22:49:31.992707 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2026-01-20 22:49:31.992730 | 
2026-01-20 22:49:32.059520 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2026-01-20 22:49:32.060218 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2026-01-20 22:49:32.588732 | 
2026-01-20 22:49:32.588866 | PLAY [localhost]
2026-01-20 22:49:32.604426 | 
2026-01-20 22:49:32.604498 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-20 22:49:32.894634 | localhost | changed
2026-01-20 22:49:32.899021 | 
2026-01-20 22:49:32.899102 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-20 22:49:32.916427 | localhost | ok
2026-01-20 22:49:32.924019 | 
2026-01-20 22:49:32.924087 | TASK [add-fileserver : Create SSH private key tempfile]
2026-01-20 22:49:33.214004 | localhost | changed
2026-01-20 22:49:33.219689 | 
2026-01-20 22:49:33.219767 | TASK [add-fileserver : Create SSH private key from secret]
2026-01-20 22:49:33.742171 | localhost | changed
2026-01-20 22:49:33.746952 | 
2026-01-20 22:49:33.747023 | TASK [add-fileserver : Add fileserver ssh key]
2026-01-20 22:49:34.067467 | localhost | Identity added: /var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/tmp/ansible.uxwwftho (/var/lib/zuul/builds/77738fc4868e49afac75e1b1c886952e/work/tmp/ansible.uxwwftho)
2026-01-20 22:49:34.067626 | localhost | ok: Runtime: 0:00:00.005843
2026-01-20 22:49:34.071687 | 
2026-01-20 22:49:34.071754 | TASK [add-fileserver : Remove SSH private key from disk]
2026-01-20 22:49:34.280690 | localhost | ok: Runtime: 0:00:00.004484
2026-01-20 22:49:34.285053 | 
2026-01-20 22:49:34.285119 | TASK [add-fileserver : Add fileserver to inventory]
2026-01-20 22:49:34.332850 | localhost | changed
2026-01-20 22:49:34.337674 | 
2026-01-20 22:49:34.337742 | TASK [add-fileserver : Add fileserver server to known hosts]
2026-01-20 22:49:34.638073 | localhost | changed
2026-01-20 22:49:34.655758 | 
2026-01-20 22:49:34.655810 | PLAY [localhost]
2026-01-20 22:49:34.666093 | 
2026-01-20 22:49:34.666154 | TASK [Generate bulk log download script]
2026-01-20 22:49:34.684068 | localhost | ok
2026-01-20 22:49:34.694616 | 
2026-01-20 22:49:34.694691 | TASK [local-log-download : Check API endpoint is defined]
2026-01-20 22:49:34.721028 | localhost | ok: All assertions passed
2026-01-20 22:49:34.725234 | 
2026-01-20 22:49:34.725317 | TASK [local-log-download : Create download script]
2026-01-20 22:49:35.051768 | localhost -> localhost | changed
2026-01-20 22:49:35.059796 | 
2026-01-20 22:49:35.059857 | TASK [Register quick-download link]
2026-01-20 22:49:35.076087 | localhost | ok
2026-01-20 22:49:35.107871 | 
2026-01-20 22:49:35.107940 | PLAY [logserver.rdoproject.org]
2026-01-20 22:49:35.117355 | 
2026-01-20 22:49:35.117415 | TASK [Set zuul-log-path fact]
2026-01-20 22:49:35.132583 | logserver.rdoproject.org | ok
2026-01-20 22:49:35.141037 | 
2026-01-20 22:49:35.141102 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-20 22:49:35.156342 | logserver.rdoproject.org | ok
2026-01-20 22:49:35.161534 | 
2026-01-20 22:49:35.161599 | TASK [upload-logs : Create log directories]
2026-01-20 22:49:37.000895 | logserver.rdoproject.org | changed
2026-01-20 22:49:37.003947 | 
2026-01-20 22:49:37.004010 | TASK [upload-logs : Ensure logs are readable before uploading]
2026-01-20 22:49:37.210045 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004078
2026-01-20 22:49:37.214522 | 
2026-01-20 22:49:37.214594 | TASK [upload-logs : Upload logs to log server]
2026-01-20 22:49:38.640250 | logserver.rdoproject.org | Output suppressed because no_log was given
2026-01-20 22:49:38.642906 | 
2026-01-20 22:49:38.642966 | LOOP [upload-logs : Compress console log and json output]
2026-01-20 22:49:38.677084 | logserver.rdoproject.org | skipping: Conditional result was False
2026-01-20 22:49:38.684703 | logserver.rdoproject.org | skipping: Conditional result was False
2026-01-20 22:49:38.689394 | 
2026-01-20 22:49:38.689471 | LOOP [upload-logs : Upload compressed console log and json output]
2026-01-20 22:49:38.722729 | logserver.rdoproject.org | skipping: Conditional result was False
2026-01-20 22:49:38.722954 | 
2026-01-20 22:49:38.726210 | logserver.rdoproject.org | skipping: Conditional result was False
2026-01-20 22:49:38.736909 | 
2026-01-20 22:49:38.736997 | LOOP [upload-logs : Upload console log and json output]