2025-09-30 08:38:32.421339 | Job console starting...
2025-09-30 08:38:32.659023 | Updating repositories
2025-09-30 08:38:33.425970 | Preparing job workspace
2025-09-30 08:38:45.532448 | Running Ansible setup...
2025-09-30 08:38:49.475348 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 08:38:50.110671 | 
2025-09-30 08:38:50.115208 | PLAY [localhost]
2025-09-30 08:38:50.130616 | 
2025-09-30 08:38:50.130736 | TASK [Gathering Facts]
2025-09-30 08:38:51.023034 | localhost | ok
2025-09-30 08:38:51.036358 | 
2025-09-30 08:38:51.036451 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 08:38:51.611474 | localhost -> localhost | changed
2025-09-30 08:38:51.616923 | 
2025-09-30 08:38:51.616996 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 08:38:52.541552 | localhost -> localhost | changed
2025-09-30 08:38:52.550473 | 
2025-09-30 08:38:52.551437 | TASK [Setup log path fact]
2025-09-30 08:38:52.599084 | localhost | ok
2025-09-30 08:38:52.610793 | 
2025-09-30 08:38:52.610882 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 08:38:52.628571 | localhost | ok
2025-09-30 08:38:52.636393 | 
2025-09-30 08:38:52.636485 | TASK [emit-job-header : Print job information]
2025-09-30 08:38:52.663592 | # Job Information
2025-09-30 08:38:52.663727 | Ansible Version: 2.15.12
2025-09-30 08:38:52.663831 | Job: cifmw-molecule-sushy_emulator
2025-09-30 08:38:52.663863 | Pipeline: github-check
2025-09-30 08:38:52.663886 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-09-30 08:38:52.663905 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333
2025-09-30 08:38:52.663954 | Log URL (when completed): https://logserver.rdoproject.org/ff4/rdoproject.org/ff41629a8ef04166b4c5f9298a576faa/
2025-09-30 08:38:52.663977 | Event ID: d16f57f0-9dd7-11f0-93f3-c9bd7262a814
2025-09-30 08:38:52.668708 | 
2025-09-30 08:38:52.668778 | LOOP [emit-job-header : Print node information]
2025-09-30 08:38:52.767349 | localhost | ok:
2025-09-30 08:38:52.767519 | localhost | # Node Information
2025-09-30 08:38:52.767550 | localhost | Inventory Hostname: controller
2025-09-30 08:38:52.767575 | localhost | Hostname: np0005462257
2025-09-30 08:38:52.767596 | localhost | Username: zuul
2025-09-30 08:38:52.767617 | localhost | Distro: CentOS 9
2025-09-30 08:38:52.767636 | localhost | Provider: ibm-bm4-nodepool
2025-09-30 08:38:52.767655 | localhost | Region: regionOne
2025-09-30 08:38:52.767672 | localhost | Label: centos-9-stream-crc-2-48-0-xl-ibm
2025-09-30 08:38:52.767689 | localhost | Product Name: OpenStack Compute
2025-09-30 08:38:52.767706 | localhost | Interface IP: 192.168.26.58
2025-09-30 08:38:52.798571 | 
2025-09-30 08:38:52.798700 | PLAY [all]
2025-09-30 08:38:52.805142 | 
2025-09-30 08:38:52.805215 | TASK [Gather network facts]
2025-09-30 08:38:53.221114 | controller | ok
2025-09-30 08:38:53.239256 | 
2025-09-30 08:38:53.239351 | TASK [include_role : start-zuul-console]
2025-09-30 08:38:53.259260 | controller | ok
2025-09-30 08:38:53.275810 | 
2025-09-30 08:38:53.275976 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 08:38:53.664105 | controller | ok
2025-09-30 08:38:53.673074 | 
2025-09-30 08:38:53.673162 | TASK [include_role : add-build-sshkey]
2025-09-30 08:38:53.691971 | controller | ok
2025-09-30 08:38:53.705383 | 
2025-09-30 08:38:53.705493 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 08:38:53.913327 | controller -> localhost | ok
2025-09-30 08:38:53.918709 | 
2025-09-30 08:38:53.918789 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 08:38:53.937127 | controller | ok
2025-09-30 08:38:53.949526 | controller | included: /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 08:38:53.955112 | 
2025-09-30 08:38:53.955174 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 08:38:54.520494 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 08:38:54.520695 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/ff41629a8ef04166b4c5f9298a576faa_id_rsa.
2025-09-30 08:38:54.520731 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/ff41629a8ef04166b4c5f9298a576faa_id_rsa.pub.
2025-09-30 08:38:54.520756 | controller -> localhost | The key fingerprint is:
2025-09-30 08:38:54.520776 | controller -> localhost | SHA256:ylF9RlVeMpuVs7cDgdZyjYUVkxPd9xAW6VrSHKDUyAw zuul-build-sshkey
2025-09-30 08:38:54.520796 | controller -> localhost | The key's randomart image is:
2025-09-30 08:38:54.520814 | controller -> localhost | +---[RSA 3072]----+
2025-09-30 08:38:54.520832 | controller -> localhost | |        E+.o=o&@@|
2025-09-30 08:38:54.520850 | controller -> localhost | |         o+*.B+&*|
2025-09-30 08:38:54.520868 | controller -> localhost | |        . + =++oB|
2025-09-30 08:38:54.520886 | controller -> localhost | |       .   o..=.o|
2025-09-30 08:38:54.520902 | controller -> localhost | |      . S    +. o|
2025-09-30 08:38:54.520943 | controller -> localhost | |     . o    .  o |
2025-09-30 08:38:54.520964 | controller -> localhost | |      o         .|
2025-09-30 08:38:54.520983 | controller -> localhost | |                 |
2025-09-30 08:38:54.521001 | controller -> localhost | |                 |
2025-09-30 08:38:54.521019 | controller -> localhost | +----[SHA256]-----+
2025-09-30 08:38:54.521068 | controller -> localhost | ok: Runtime: 0:00:00.216985
2025-09-30 08:38:54.526684 | 
2025-09-30 08:38:54.526751 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 08:38:54.544882 | controller | ok
2025-09-30 08:38:54.554664 | controller | included: /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 08:38:54.563517 | 
2025-09-30 08:38:54.563608 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 08:38:54.577298 | controller | skipping: Conditional result was False
2025-09-30 08:38:54.583405 | 
2025-09-30 08:38:54.583516 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 08:38:55.069498 | controller | changed
2025-09-30 08:38:55.074449 | 
2025-09-30 08:38:55.074543 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 08:38:55.335660 | controller | ok
2025-09-30 08:38:55.340884 | 
2025-09-30 08:38:55.340985 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 08:38:56.422625 | controller | changed
2025-09-30 08:38:56.428450 | 
2025-09-30 08:38:56.428527 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 08:38:57.503877 | controller | changed
2025-09-30 08:38:57.508577 | 
2025-09-30 08:38:57.508667 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 08:38:57.522162 | controller | skipping: Conditional result was False
2025-09-30 08:38:57.527860 | 
2025-09-30 08:38:57.527942 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 08:38:57.856082 | controller -> localhost | changed
2025-09-30 08:38:57.867154 | 
2025-09-30 08:38:57.867230 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 08:38:58.114213 | controller -> localhost | Identity added: /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/ff41629a8ef04166b4c5f9298a576faa_id_rsa (zuul-build-sshkey)
2025-09-30 08:38:58.114407 | controller -> localhost | ok: Runtime: 0:00:00.007103
2025-09-30 08:38:58.121962 | 
2025-09-30 08:38:58.122027 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 08:38:58.482350 | controller | ok
2025-09-30 08:38:58.486989 | 
2025-09-30 08:38:58.487058 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 08:38:58.516519 | controller | skipping: Conditional result was False
2025-09-30 08:38:58.525848 | 
2025-09-30 08:38:58.525941 | TASK [include_role : validate-host]
2025-09-30 08:38:58.543698 | controller | ok
2025-09-30 08:38:58.562252 | 
2025-09-30 08:38:58.562319 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-30 08:38:58.589993 | controller | ok
2025-09-30 08:38:58.594703 | 
2025-09-30 08:38:58.594765 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-30 08:38:58.812524 | controller -> localhost | ok
2025-09-30 08:38:58.838014 | 
2025-09-30 08:38:58.838110 | TASK [validate-host : Collect information about the host]
2025-09-30 08:38:59.515347 | controller | ok
2025-09-30 08:38:59.523519 | 
2025-09-30 08:38:59.523584 | TASK [validate-host : Sanitize hostname]
2025-09-30 08:38:59.571866 | controller | ok
2025-09-30 08:38:59.577434 | 
2025-09-30 08:38:59.577514 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-30 08:38:59.988092 | controller -> localhost | changed
2025-09-30 08:38:59.993388 | 
2025-09-30 08:38:59.993452 | TASK [validate-host : Collect information about zuul worker]
2025-09-30 08:39:00.376875 | controller | ok
2025-09-30 08:39:00.381574 | 
2025-09-30 08:39:00.381642 | TASK [validate-host : Write out all zuul information for each host]
2025-09-30 08:39:00.760543 | controller -> localhost | changed
2025-09-30 08:39:00.769533 | 
2025-09-30 08:39:00.769597 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 08:39:00.782776 | controller | skipping: Conditional result was False
2025-09-30 08:39:00.787654 | 
2025-09-30 08:39:00.787723 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 08:39:00.800989 | controller | skipping: Conditional result was False
2025-09-30 08:39:00.805873 | 
2025-09-30 08:39:00.805952 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 08:39:01.055585 | controller | ok: "logs"
2025-09-30 08:39:01.055834 | controller | ok: All items complete
2025-09-30 08:39:01.055864 | 
2025-09-30 08:39:01.276754 | controller | ok: "artifacts"
2025-09-30 08:39:01.506657 | controller | ok: "docs"
2025-09-30 08:39:01.522517 | 
2025-09-30 08:39:01.522618 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 08:39:01.775242 | controller | changed: "logs"
2025-09-30 08:39:02.002093 | controller | changed: "artifacts"
2025-09-30 08:39:02.239109 | controller | changed: "docs"
2025-09-30 08:39:02.268287 | 
2025-09-30 08:39:02.268370 | PLAY RECAP
2025-09-30 08:39:02.268416 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 08:39:02.268445 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 08:39:02.268488 | 
2025-09-30 08:39:02.347026 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 08:39:02.347730 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-30 08:39:02.907554 | 
2025-09-30 08:39:02.907658 | PLAY [all]
2025-09-30 08:39:02.927791 | 
2025-09-30 08:39:02.927875 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-30 08:39:02.976942 | controller | ok
2025-09-30 08:39:02.981945 | 
2025-09-30 08:39:02.982030 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-30 08:39:03.377821 | controller | changed
2025-09-30 08:39:03.383524 | 
2025-09-30 08:39:03.383602 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-30 08:39:04.568958 | controller | changed
2025-09-30 08:39:04.579494 | 
2025-09-30 08:39:04.579565 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-09-30 08:39:05.017129 | controller | changed:
2025-09-30 08:39:05.017308 | controller | {
2025-09-30 08:39:05.017343 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-09-30 08:39:05.017980 | controller | }
2025-09-30 08:39:05.324123 | controller | changed:
2025-09-30 08:39:05.325394 | controller | {
2025-09-30 08:39:05.325455 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-09-30 08:39:05.325496 | controller | }
2025-09-30 08:39:05.620709 | controller | changed:
2025-09-30 08:39:05.620796 | controller | {
2025-09-30 08:39:05.620824 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-09-30 08:39:05.620845 | controller | }
2025-09-30 08:39:05.899278 | controller | changed:
2025-09-30 08:39:05.899366 | controller | {
2025-09-30 08:39:05.899393 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-09-30 08:39:05.899413 | controller | }
2025-09-30 08:39:06.171798 | controller | changed:
2025-09-30 08:39:06.171959 | controller | {
2025-09-30 08:39:06.171994 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-09-30 08:39:06.172016 | controller | }
2025-09-30 08:39:06.460832 | controller | changed:
2025-09-30 08:39:06.460938 | controller | {
2025-09-30 08:39:06.460970 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-09-30 08:39:06.460993 | controller | }
2025-09-30 08:39:06.745859 | controller | changed:
2025-09-30 08:39:06.745967 | controller | {
2025-09-30 08:39:06.745996 | 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"
2025-09-30 08:39:06.746018 | controller | }
2025-09-30 08:39:07.034899 | controller | changed:
2025-09-30 08:39:07.034993 | controller | {
2025-09-30 08:39:07.035022 | 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"
2025-09-30 08:39:07.035044 | controller | }
2025-09-30 08:39:07.316505 | controller | changed:
2025-09-30 08:39:07.316660 | controller | {
2025-09-30 08:39:07.316697 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-09-30 08:39:07.316720 | controller | }
2025-09-30 08:39:07.620761 | controller | changed:
2025-09-30 08:39:07.621005 | controller | {
2025-09-30 08:39:07.621034 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-09-30 08:39:07.621054 | controller | }
2025-09-30 08:39:07.887645 | controller | changed:
2025-09-30 08:39:07.887727 | controller | {
2025-09-30 08:39:07.887753 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-09-30 08:39:07.887773 | controller | }
2025-09-30 08:39:08.164529 | controller | changed:
2025-09-30 08:39:08.164617 | controller | {
2025-09-30 08:39:08.164662 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-09-30 08:39:08.164689 | controller | }
2025-09-30 08:39:08.445903 | controller | changed:
2025-09-30 08:39:08.446002 | controller | {
2025-09-30 08:39:08.446030 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-09-30 08:39:08.446052 | controller | }
2025-09-30 08:39:08.731624 | controller | changed:
2025-09-30 08:39:08.731796 | controller | {
2025-09-30 08:39:08.731833 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-09-30 08:39:08.731855 | controller | }
2025-09-30 08:39:09.027940 | controller | changed:
2025-09-30 08:39:09.028017 | controller | {
2025-09-30 08:39:09.028045 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-09-30 08:39:09.028067 | controller | }
2025-09-30 08:39:09.304752 | controller | changed:
2025-09-30 08:39:09.304963 | controller | {
2025-09-30 08:39:09.305009 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-09-30 08:39:09.305034 | controller | }
2025-09-30 08:39:09.586101 | controller | changed:
2025-09-30 08:39:09.586174 | controller | {
2025-09-30 08:39:09.586204 | 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"
2025-09-30 08:39:09.586230 | controller | }
2025-09-30 08:39:09.863187 | controller | changed:
2025-09-30 08:39:09.863285 | controller | {
2025-09-30 08:39:09.863320 | 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"
2025-09-30 08:39:09.863441 | controller | }
2025-09-30 08:39:10.151502 | controller | changed:
2025-09-30 08:39:10.151583 | controller | {
2025-09-30 08:39:10.151611 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-09-30 08:39:10.151633 | controller | }
2025-09-30 08:39:10.449826 | controller | changed:
2025-09-30 08:39:10.449987 | controller | {
2025-09-30 08:39:10.450024 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-09-30 08:39:10.450049 | controller | }
2025-09-30 08:39:10.753017 | controller | changed:
2025-09-30 08:39:10.753101 | controller | {
2025-09-30 08:39:10.753129 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-09-30 08:39:10.753150 | controller | }
2025-09-30 08:39:11.037051 | controller | changed:
2025-09-30 08:39:11.037139 | controller | {
2025-09-30 08:39:11.037165 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-09-30 08:39:11.037186 | controller | }
2025-09-30 08:39:11.323617 | controller | changed:
2025-09-30 08:39:11.323696 | controller | {
2025-09-30 08:39:11.323723 | 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"
2025-09-30 08:39:11.323744 | controller | }
2025-09-30 08:39:11.601678 | controller | changed:
2025-09-30 08:39:11.601754 | controller | {
2025-09-30 08:39:11.601780 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-09-30 08:39:11.601800 | controller | }
2025-09-30 08:39:11.881428 | controller | changed:
2025-09-30 08:39:11.881560 | controller | {
2025-09-30 08:39:11.881591 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-09-30 08:39:11.881613 | controller | }
2025-09-30 08:39:12.156330 | controller | changed:
2025-09-30 08:39:12.156403 | controller | {
2025-09-30 08:39:12.156431 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-09-30 08:39:12.156452 | controller | }
2025-09-30 08:39:12.181707 | 
2025-09-30 08:39:12.181777 | TASK [Set timezone to UTC]
2025-09-30 08:39:12.655813 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-09-30 08:39:12.660708 | 
2025-09-30 08:39:12.660786 | TASK [Create nodepool directory]
2025-09-30 08:39:12.922898 | controller | changed
2025-09-30 08:39:12.930277 | 
2025-09-30 08:39:12.930388 | TASK [Create nodepool sub_nodes file]
2025-09-30 08:39:13.853544 | controller | changed
2025-09-30 08:39:13.880052 | 
2025-09-30 08:39:13.880172 | TASK [Create nodepool sub_nodes_private file]
2025-09-30 08:39:14.846817 | controller | changed
2025-09-30 08:39:14.851677 | 
2025-09-30 08:39:14.851742 | LOOP [Populate nodepool sub_nodes file]
2025-09-30 08:39:14.881261 | 
2025-09-30 08:39:14.881406 | LOOP [Populate nodepool sub_nodes_private file]
2025-09-30 08:39:14.910017 | 
2025-09-30 08:39:14.910162 | TASK [Create nodepool primary file]
2025-09-30 08:39:14.933068 | controller | skipping: Conditional result was False
2025-09-30 08:39:14.938746 | 
2025-09-30 08:39:14.938822 | TASK [Create nodepool node_private for this node]
2025-09-30 08:39:15.878757 | controller | changed
2025-09-30 08:39:15.886415 | 
2025-09-30 08:39:15.886545 | LOOP [Copy ssh keys to nodepool directory]
2025-09-30 08:39:16.273657 | controller | ok: Item: id_rsa Runtime: 0:00:00.004420
2025-09-30 08:39:16.273836 | 
2025-09-30 08:39:16.493629 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.004610
2025-09-30 08:39:16.508682 | 
2025-09-30 08:39:16.508790 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-09-30 08:39:17.431287 | controller | changed
2025-09-30 08:39:17.436557 | 
2025-09-30 08:39:17.436620 | TASK [Validate sudoers config after edits]
2025-09-30 08:39:17.709955 | controller | /etc/sudoers: parsed OK
2025-09-30 08:39:17.710022 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-09-30 08:39:17.710033 | controller | /etc/sudoers.d/zuul: parsed OK
2025-09-30 08:39:17.710039 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-09-30 08:39:17.963048 | controller | ok: Runtime: 0:00:00.005041
2025-09-30 08:39:17.968537 | 
2025-09-30 08:39:17.968604 | TASK [Show the environment passed in to job shell scripts]
2025-09-30 08:39:18.225574 | controller | SHELL=/bin/bash
2025-09-30 08:39:18.225614 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-09-30 08:39:18.225624 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-09-30 08:39:18.225629 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/46/3346/eb5b53fb17db92a72d33d052a56c8edd0d10ea78^openstack-k8s-operators/ci-framework:main:refs/changes/52/3352/d2778ae73606ebdeaebbcd175cb35e14655ec370^openstack-k8s-operators/ci-framework:main:refs/changes/33/3333/b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 08:39:18.225635 | controller | PWD=/home/zuul
2025-09-30 08:39:18.225641 | controller | ZUUL_PIPELINE=github-check
2025-09-30 08:39:18.225646 | controller | LOGNAME=zuul
2025-09-30 08:39:18.225651 | controller | XDG_SESSION_TYPE=tty
2025-09-30 08:39:18.225656 | controller | _=/usr/bin/env
2025-09-30 08:39:18.225662 | controller | MOTD_SHOWN=pam
2025-09-30 08:39:18.225706 | controller | HOME=/home/zuul
2025-09-30 08:39:18.225714 | controller | LANG=en_US.UTF-8
2025-09-30 08:39:18.225719 | controller | SSH_CONNECTION=192.168.26.12 58290 192.168.26.58 22
2025-09-30 08:39:18.225725 | 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
2025-09-30 08:39:18.225733 | controller | ZUUL_CHANGE_IDS=3346,eb5b53fb17db92a72d33d052a56c8edd0d10ea78 3352,d2778ae73606ebdeaebbcd175cb35e14655ec370 3333,b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 08:39:18.225738 | controller | WORKSPACE=/home/zuul/workspace
2025-09-30 08:39:18.225743 | controller | XDG_SESSION_CLASS=user
2025-09-30 08:39:18.225748 | controller | SELINUX_ROLE_REQUESTED=
2025-09-30 08:39:18.225753 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-09-30 08:39:18.225758 | controller | USER=zuul
2025-09-30 08:39:18.225764 | controller | ZUUL_VOTING=True
2025-09-30 08:39:18.225769 | controller | BUILD_TIMEOUT=1800000
2025-09-30 08:39:18.225774 | controller | SELINUX_USE_CURRENT_RANGE=
2025-09-30 08:39:18.225779 | controller | SHLVL=1
2025-09-30 08:39:18.225784 | controller | ZUUL_PATCHSET=b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 08:39:18.225789 | controller | XDG_SESSION_ID=1
2025-09-30 08:39:18.225794 | controller | ZUUL_BRANCH=main
2025-09-30 08:39:18.225799 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-09-30 08:39:18.225805 | controller | SSH_CLIENT=192.168.26.12 58290 22
2025-09-30 08:39:18.225810 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-09-30 08:39:18.225815 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-09-30 08:39:18.225820 | controller | which_declare=declare -f
2025-09-30 08:39:18.225825 | controller | PATH=/home/zuul/.crc/bin/oc:/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-09-30 08:39:18.225830 | controller | SELINUX_LEVEL_REQUESTED=
2025-09-30 08:39:18.225835 | controller | ZUUL_CHANGE=3333
2025-09-30 08:39:18.225840 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-09-30 08:39:18.225845 | controller | ZUUL_UUID=ff41629a8ef04166b4c5f9298a576faa
2025-09-30 08:39:18.225852 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-09-30 08:39:18.225857 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-09-30 08:39:18.225862 | controller | }
2025-09-30 08:39:18.495243 | controller | ok: Runtime: 0:00:00.005308
2025-09-30 08:39:18.500797 | 
2025-09-30 08:39:18.500862 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-09-30 08:39:18.514506 | controller | skipping: Conditional result was False
2025-09-30 08:39:18.519672 | 
2025-09-30 08:39:18.519745 | TASK [Symlink /home/zuul-worker/workspace]
2025-09-30 08:39:19.061703 | controller | skipping: Conditional result was False
2025-09-30 08:39:19.067346 | 
2025-09-30 08:39:19.067417 | TASK [Ensure legacy workspace directory]
2025-09-30 08:39:19.308778 | controller | changed
2025-09-30 08:39:19.340667 | 
2025-09-30 08:39:19.340778 | PLAY RECAP
2025-09-30 08:39:19.340826 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 08:39:19.340848 | 
2025-09-30 08:39:19.418981 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-30 08:39:19.419682 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-30 08:39:19.963939 | 
2025-09-30 08:39:19.964045 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-09-30 08:39:19.994130 | 
2025-09-30 08:39:19.994207 | TASK [Create zuul-output directory]
2025-09-30 08:39:20.378150 | controller | changed
2025-09-30 08:39:20.384060 | 
2025-09-30 08:39:20.384149 | TASK [Slurp Zuul inventory test]
2025-09-30 08:39:20.671924 | controller -> localhost | ok
2025-09-30 08:39:20.678304 | 
2025-09-30 08:39:20.678377 | TASK [Save zuul inventory]
2025-09-30 08:39:21.832590 | controller | changed
2025-09-30 08:39:21.837969 | 
2025-09-30 08:39:21.838037 | TASK [Save zuul vars without the change_message]
2025-09-30 08:39:22.850522 | controller | changed
2025-09-30 08:39:22.869046 | 
2025-09-30 08:39:22.869136 | PLAY RECAP
2025-09-30 08:39:22.869190 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 08:39:22.869218 | 
2025-09-30 08:39:22.944127 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-30 08:39:22.944849 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-30 08:39:23.504720 | 
2025-09-30 08:39:23.504821 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-09-30 08:39:23.526400 | 
2025-09-30 08:39:23.526485 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-09-30 08:39:23.556085 | controller | ok
2025-09-30 08:39:23.573584 | 
2025-09-30 08:39:23.573668 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-30 08:39:23.598629 | controller | skipping: Conditional result was False
2025-09-30 08:39:23.607675 | 
2025-09-30 08:39:23.607845 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-30 08:39:23.992690 | controller | ok
2025-09-30 08:39:23.998721 | 
2025-09-30 08:39:23.998799 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-30 08:39:24.870546 | controller | ok
2025-09-30 08:39:24.880072 | 
2025-09-30 08:39:24.880139 | TASK [Prepare workspace]
2025-09-30 08:39:24.897869 | controller | ok
2025-09-30 08:39:24.914269 | 
2025-09-30 08:39:24.914340 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 08:39:25.260609 | controller | ok
2025-09-30 08:39:25.266160 | 
2025-09-30 08:39:25.266225 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 08:39:27.189888 | controller | Output suppressed because no_log was given
2025-09-30 08:39:27.199360 | 
2025-09-30 08:39:27.199443 | LOOP [Create zuul-output directory]
2025-09-30 08:39:27.452881 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-09-30 08:39:27.665578 | controller | ok: "/home/zuul/zuul-output/logs"
2025-09-30 08:39:27.678407 | 
2025-09-30 08:39:27.678529 | TASK [Install required packages]
2025-09-30 08:39:46.156974 | controller | ok: Nothing to do
2025-09-30 08:39:46.162601 | 
2025-09-30 08:39:46.162679 | TASK [Install venv]
2025-09-30 08:40:43.810094 | controller | changed
2025-09-30 08:40:43.835245 | 
2025-09-30 08:40:43.835325 | PLAY RECAP
2025-09-30 08:40:43.835371 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 08:40:43.835395 | 
2025-09-30 08:40:43.920079 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-30 08:40:43.921023 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-30 08:40:44.446467 | 
2025-09-30 08:40:44.446588 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-09-30 08:40:44.467010 | 
2025-09-30 08:40:44.467090 | TASK [Gather required facts]
2025-09-30 08:40:45.024091 | controller | ok
2025-09-30 08:40:45.029811 | 
2025-09-30 08:40:45.029951 | TASK [Load environment var if instructed to]
2025-09-30 08:40:45.054306 | controller | skipping: Conditional result was False
2025-09-30 08:40:45.060488 | 
2025-09-30 08:40:45.060602 | TASK [Run molecule]
2025-09-30 08:40:46.054257 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-09-30 08:40:46.126853 | controller | INFO     Performing prerun with role_name_check=0...
2025-09-30 08:41:02.819350 | 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).
2025-09-30 08:41:02.820072 | 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).
2025-09-30 08:41:02.820615 | 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).
2025-09-30 08:41:02.821071 | 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).
2025-09-30 08:41:02.821576 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+141b665d was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0+141b665d (/home/zuul/.ansible/collections/ansible_collections).
2025-09-30 08:41:02.822193 | 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).
2025-09-30 08:41:02.822654 | 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).
2025-09-30 08:41:02.823091 | 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).
2025-09-30 08:41:02.823543 | 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).
2025-09-30 08:41:02.823968 | 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).
2025-09-30 08:41:02.824452 | 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).
2025-09-30 08:41:02.824891 | 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).
2025-09-30 08:41:02.825371 | 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).
2025-09-30 08:41:02.825815 | 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).
2025-09-30 08:41:02.826274 | 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).
2025-09-30 08:41:02.835779 | controller | INFO     Running default > prepare
2025-09-30 08:41:03.501934 | controller |
2025-09-30 08:41:03.502001 | controller | PLAY [Prepare] *****************************************************************
2025-09-30 08:41:03.502343 | controller |
2025-09-30 08:41:03.502422 | controller | TASK [Gathering Facts] *********************************************************
2025-09-30 08:41:03.502519 | controller | Tuesday 30 September 2025  08:41:03 +0000 (0:00:00.013)       0:00:00.013 *****
2025-09-30 08:41:04.345391 | controller | ok: [instance]
2025-09-30 08:41:04.345462 | controller |
2025-09-30 08:41:04.345566 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-09-30 08:41:04.345667 | controller | Tuesday 30 September 2025  08:41:04 +0000 (0:00:00.844)       0:00:00.857 *****
2025-09-30 08:41:04.362894 | controller | skipping: [instance]
2025-09-30 08:41:04.363002 | controller |
2025-09-30 08:41:04.363138 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-09-30 08:41:04.363280 | controller | Tuesday 30 September 2025  08:41:04 +0000 (0:00:00.017)       0:00:00.875 *****
2025-09-30 08:41:04.405013 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-09-30 08:41:04.405117 | controller |
2025-09-30 08:41:04.405258 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-09-30 08:41:04.405410 | controller | Tuesday 30 September 2025  08:41:04 +0000 (0:00:00.041)       0:00:00.917 *****
2025-09-30 08:41:04.694645 | controller | ok: [instance]
2025-09-30 08:41:04.694698 | controller |
2025-09-30 08:41:04.694797 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-09-30 08:41:04.694904 | controller | Tuesday 30 September 2025  08:41:04 +0000 (0:00:00.289)       0:00:01.207 *****
2025-09-30 08:41:05.007124 | controller | ok: [instance]
2025-09-30 08:41:05.007235 | controller |
2025-09-30 08:41:05.007388 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-09-30 08:41:05.007517 | controller | Tuesday 30 September 2025  08:41:05 +0000 (0:00:00.312)       0:00:01.519 *****
2025-09-30 08:41:05.708604 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-09-30 08:41:05.708679 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-09-30 08:41:05.708783 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-09-30 08:41:05.708878 | controller |
2025-09-30 08:41:05.708977 | controller | TASK [Deploy repo-setup] *******************************************************
2025-09-30 08:41:05.709070 | controller | Tuesday 30 September 2025  08:41:05 +0000 (0:00:00.701)       0:00:02.221 *****
2025-09-30 08:41:05.770073 | controller |
2025-09-30 08:41:05.770172 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-09-30 08:41:05.770361 | controller | Tuesday 30 September 2025  08:41:05 +0000 (0:00:00.061)       0:00:02.282 *****
2025-09-30 08:41:06.312479 | controller | changed: [instance] => (item=tmp)
2025-09-30 08:41:06.312563 | controller | changed: [instance] => (item=artifacts/repositories)
2025-09-30 08:41:06.312673 | controller | changed: [instance] => (item=venv/repo_setup)
2025-09-30 08:41:06.312769 | controller |
2025-09-30 08:41:06.312877 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-09-30 08:41:06.312966 | controller | Tuesday 30 September 2025  08:41:06 +0000 (0:00:00.542)       0:00:02.824 *****
2025-09-30 08:41:07.125730 | controller | ok: [instance]
2025-09-30 08:41:07.126054 | controller |
2025-09-30 08:41:08.301587 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-09-30 08:41:08.301621 | controller | Tuesday 30 September 2025  08:41:07 +0000 (0:00:00.813)       0:00:03.638 *****
2025-09-30 08:41:08.301632 | controller | changed: [instance]
2025-09-30 08:41:16.212478 | controller |
2025-09-30 08:41:16.212518 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-09-30 08:41:16.212527 | controller | Tuesday 30 September 2025  08:41:08 +0000 (0:00:01.175)       0:00:04.813 *****
2025-09-30 08:41:16.212537 | controller | changed: [instance]
2025-09-30 08:41:16.943257 | controller |
2025-09-30 08:41:16.943300 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-09-30 08:41:16.943310 | controller | Tuesday 30 September 2025  08:41:16 +0000 (0:00:07.910)       0:00:12.724 *****
2025-09-30 08:41:16.943330 | controller | changed: [instance]
2025-09-30 08:41:16.943351 | controller |
2025-09-30 08:41:16.943360 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-09-30 08:41:16.943497 | controller | Tuesday 30 September 2025  08:41:16 +0000 (0:00:00.730)       0:00:13.455 *****
2025-09-30 08:41:16.965647 | controller | skipping: [instance]
2025-09-30 08:41:17.780206 | controller |
2025-09-30 08:41:17.780240 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-09-30 08:41:17.780249 | controller | Tuesday 30 September 2025  08:41:16 +0000 (0:00:00.022)       0:00:13.477 *****
2025-09-30 08:41:17.780261 | controller | changed: [instance]
2025-09-30 08:41:17.780289 | controller |
2025-09-30 08:41:17.780299 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-09-30 08:41:17.780326 | controller | Tuesday 30 September 2025  08:41:17 +0000 (0:00:00.814)       0:00:14.292 *****
2025-09-30 08:41:17.815689 | controller | skipping: [instance]
2025-09-30 08:41:17.851903 | controller |
2025-09-30 08:41:17.851936 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-09-30 08:41:17.851945 | controller | Tuesday 30 September 2025  08:41:17 +0000 (0:00:00.035)       0:00:14.327 *****
2025-09-30 08:41:17.851955 | controller | skipping: [instance]
2025-09-30 08:41:17.920857 | controller |
2025-09-30 08:41:17.920889 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-09-30 08:41:17.920897 | controller | Tuesday 30 September 2025  08:41:17 +0000 (0:00:00.035)       0:00:14.363 *****
2025-09-30 08:41:17.920908 | controller | skipping: [instance]
2025-09-30 08:41:18.465130 | controller |
2025-09-30 08:41:18.465166 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-09-30 08:41:18.465174 | controller | Tuesday 30 September 2025  08:41:17 +0000 (0:00:00.069)       0:00:14.433 *****
2025-09-30 08:41:18.465183 | controller | changed: [instance]
2025-09-30 08:41:18.898197 | controller |
2025-09-30 08:41:18.898225 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-09-30 08:41:18.898233 | controller | Tuesday 30 September 2025  08:41:18 +0000 (0:00:00.544)       0:00:14.977 *****
2025-09-30 08:41:18.898243 | controller | changed: [instance]
2025-09-30 08:41:18.898269 | controller |
2025-09-30 08:41:18.898562 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-09-30 08:41:18.924741 | controller | Tuesday 30 September 2025  08:41:18 +0000 (0:00:00.433)       0:00:15.410 *****
2025-09-30 08:41:18.924763 | controller | skipping: [instance]
2025-09-30 08:41:18.954182 | controller |
2025-09-30 08:41:18.954210 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-09-30 08:41:18.954218 | controller | Tuesday 30 September 2025  08:41:18 +0000 (0:00:00.026)       0:00:15.437 *****
2025-09-30 08:41:18.954231 | controller | skipping: [instance]
2025-09-30 08:41:18.954237 | controller |
2025-09-30 08:41:18.954243 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-09-30 08:41:18.954250 | controller | Tuesday 30 September 2025  08:41:18 +0000 (0:00:00.029)       0:00:15.466 *****
2025-09-30 08:41:18.984704 | controller | skipping: [instance]
2025-09-30 08:41:19.082687 | controller |
2025-09-30 08:41:19.082714 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-09-30 08:41:19.082724 | controller | Tuesday 30 September 2025  08:41:18 +0000 (0:00:00.030)       0:00:15.497 *****
2025-09-30 08:41:19.082735 | controller | ok: [instance]
2025-09-30 08:41:19.111393 | controller |
2025-09-30 08:41:19.111415 | controller | TASK [repo_setup : Create download directory] **********************************
2025-09-30 08:41:19.111424 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.097)       0:00:15.594 *****
2025-09-30 08:41:19.111434 | controller | skipping: [instance]
2025-09-30 08:41:19.111608 | controller |
2025-09-30 08:41:19.111780 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-09-30 08:41:19.111957 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.029)       0:00:15.624 *****
2025-09-30 08:41:19.138817 | controller | skipping: [instance]
2025-09-30 08:41:19.138981 | controller |
2025-09-30 08:41:19.139145 | controller | TASK [Download the RPM] ********************************************************
2025-09-30 08:41:19.139290 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.027)       0:00:15.651 *****
2025-09-30 08:41:19.166388 | controller | skipping: [instance]
2025-09-30 08:41:19.166572 | controller |
2025-09-30 08:41:19.166743 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-09-30 08:41:19.166907 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.027)       0:00:15.679 *****
2025-09-30 08:41:19.194054 | controller | skipping: [instance]
2025-09-30 08:41:19.194275 | controller |
2025-09-30 08:41:19.194455 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-09-30 08:41:19.194624 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.027)       0:00:15.706 *****
2025-09-30 08:41:19.221273 | controller | skipping: [instance]
2025-09-30 08:41:19.221459 | controller |
2025-09-30 08:41:19.221634 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-09-30 08:41:19.221801 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.027)       0:00:15.734 *****
2025-09-30 08:41:19.250935 | controller | skipping: [instance]
2025-09-30 08:41:19.251138 | controller |
2025-09-30 08:41:19.251303 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-09-30 08:41:19.251447 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.029)       0:00:15.763 *****
2025-09-30 08:41:19.276290 | controller | skipping: [instance]
2025-09-30 08:41:19.276434 | controller |
2025-09-30 08:41:19.276575 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-09-30 08:41:19.276709 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.025)       0:00:15.789 *****
2025-09-30 08:41:19.463836 | controller | ok: [instance]
2025-09-30 08:41:19.671183 | controller |
2025-09-30 08:41:19.671220 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-09-30 08:41:19.671228 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.186)       0:00:15.975 *****
2025-09-30 08:41:19.671239 | controller | changed: [instance]
2025-09-30 08:41:19.671263 | controller |
2025-09-30 08:41:19.671271 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-09-30 08:41:19.671444 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.207)       0:00:16.183 *****
2025-09-30 08:41:19.892584 | controller | changed: [instance]
2025-09-30 08:41:19.913087 | controller |
2025-09-30 08:41:19.913131 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-09-30 08:41:19.913144 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.221)       0:00:16.404 *****
2025-09-30 08:41:19.913156 | controller | skipping: [instance]
2025-09-30 08:41:19.933239 | controller |
2025-09-30 08:41:19.933275 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-09-30 08:41:19.933285 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.020)       0:00:16.425 *****
2025-09-30 08:41:19.933297 | controller | skipping: [instance]
2025-09-30 08:41:19.933328 | controller |
2025-09-30 08:41:19.933541 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-09-30 08:41:19.955590 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.020)       0:00:16.445 *****
2025-09-30 08:41:19.955621 | controller | skipping: [instance]
2025-09-30 08:41:19.978239 | controller |
2025-09-30 08:41:19.978271 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-09-30 08:41:19.978280 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.022)       0:00:16.468 *****
2025-09-30 08:41:19.978296 | controller | skipping: [instance]
2025-09-30 08:41:19.978327 | controller |
2025-09-30 08:41:19.978338 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-09-30 08:41:19.978499 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.022)       0:00:16.490 *****
2025-09-30 08:41:19.999778 | controller | skipping: [instance]
2025-09-30 08:41:20.020166 | controller |
2025-09-30 08:41:20.020195 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-09-30 08:41:20.020214 | controller | Tuesday 30 September 2025  08:41:19 +0000 (0:00:00.021)       0:00:16.512 *****
2025-09-30 08:41:20.020227 | controller | skipping: [instance]
2025-09-30 08:41:20.034722 | controller |
2025-09-30 08:41:20.034744 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-09-30 08:41:20.034752 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.020)       0:00:16.532 *****
2025-09-30 08:41:20.034761 | controller | skipping: [instance]
2025-09-30 08:41:20.034876 | controller |
2025-09-30 08:41:20.035054 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-09-30 08:41:20.035236 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.015)       0:00:16.547 *****
2025-09-30 08:41:20.062071 | controller | skipping: [instance]
2025-09-30 08:41:20.062252 | controller |
2025-09-30 08:41:20.062410 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-09-30 08:41:20.062556 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.027)       0:00:16.574 *****
2025-09-30 08:41:20.077233 | controller | skipping: [instance]
2025-09-30 08:41:20.077394 | controller |
2025-09-30 08:41:20.077545 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-09-30 08:41:20.077691 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.015)       0:00:16.590 *****
2025-09-30 08:41:20.096145 | controller | skipping: [instance]
2025-09-30 08:41:20.096312 | controller |
2025-09-30 08:41:20.096465 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-09-30 08:41:20.096612 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.018)       0:00:16.608 *****
2025-09-30 08:41:20.123975 | controller | skipping: [instance]
2025-09-30 08:41:20.124157 | controller |
2025-09-30 08:41:20.124349 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-09-30 08:41:20.124470 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.027)       0:00:16.636 *****
2025-09-30 08:41:20.151516 | controller | skipping: [instance]
2025-09-30 08:41:20.151647 | controller |
2025-09-30 08:41:20.151839 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-09-30 08:41:20.151951 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.027)       0:00:16.664 *****
2025-09-30 08:41:20.179314 | controller | skipping: [instance]
2025-09-30 08:41:20.179443 | controller |
2025-09-30 08:41:20.179633 | controller | TASK [test_deps : Install additional packages] *********************************
2025-09-30 08:41:20.179747 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.027)       0:00:16.692 *****
2025-09-30 08:41:20.208115 | controller | skipping: [instance]
2025-09-30 08:41:20.208307 | controller |
2025-09-30 08:41:20.208414 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-09-30 08:41:20.208611 | controller | Tuesday 30 September 2025  08:41:20 +0000 (0:00:00.028)       0:00:16.720 *****
2025-09-30 08:42:01.046801 | controller | ok: [instance]
2025-09-30 08:42:02.255958 | controller |
2025-09-30 08:42:02.255990 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-09-30 08:42:02.255998 | controller | Tuesday 30 September 2025  08:42:01 +0000 (0:00:40.838)       0:00:57.559 *****
2025-09-30 08:42:02.256008 | controller | ok: [instance]
2025-09-30 08:42:02.287651 | controller |
2025-09-30 08:42:02.287674 | controller | TASK [test_deps : Install extra packages] **************************************
2025-09-30 08:42:02.287683 | controller | Tuesday 30 September 2025  08:42:02 +0000 (0:00:01.209)       0:00:58.768 *****
2025-09-30 08:42:02.287693 | controller | skipping: [instance]
2025-09-30 08:44:44.920888 | controller |
2025-09-30 08:44:44.920929 | controller | TASK [Ensure CRC is started] ***************************************************
2025-09-30 08:44:44.920937 | controller | Tuesday 30 September 2025  08:42:02 +0000 (0:00:00.031)       0:00:58.800 *****
2025-09-30 08:44:44.920947 | controller | changed: [instance]
2025-09-30 08:44:45.234265 | controller |
2025-09-30 08:44:45.234321 | controller | TASK [Inject crc hostname/IP in hosts] *****************************************
2025-09-30 08:44:45.234331 | controller | Tuesday 30 September 2025  08:44:44 +0000 (0:02:42.632)       0:03:41.432 *****
2025-09-30 08:44:45.234342 | controller | changed: [instance]
2025-09-30 08:44:45.234380 | controller |
2025-09-30 08:44:45.234390 | controller | PLAY RECAP *********************************************************************
2025-09-30 08:44:45.235971 | controller | instance                   : ok=21   changed=11   unreachable=0    failed=0    skipped=30   rescued=0    ignored=0
2025-09-30 08:44:45.235996 | controller |
2025-09-30 08:44:45.236014 | controller | Tuesday 30 September 2025  08:44:45 +0000 (0:00:00.313)       0:03:41.746 *****
2025-09-30 08:44:45.236060 | controller | ===============================================================================
2025-09-30 08:44:45.236068 | controller | Ensure CRC is started ------------------------------------------------- 162.63s
2025-09-30 08:44:45.236073 | controller | test_deps : Install selinux python libs -------------------------------- 40.84s
2025-09-30 08:44:45.236078 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.91s
2025-09-30 08:44:45.236084 | controller | test_deps : Install python yaml libs ------------------------------------ 1.21s
2025-09-30 08:44:45.236089 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.18s
2025-09-30 08:44:45.236094 | controller | Gathering Facts --------------------------------------------------------- 0.84s
2025-09-30 08:44:45.236099 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.81s
2025-09-30 08:44:45.236121 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.81s
2025-09-30 08:44:45.236127 | controller | repo_setup : Install repo-setup package --------------------------------- 0.73s
2025-09-30 08:44:45.236132 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.70s
2025-09-30 08:44:45.236137 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.54s
2025-09-30 08:44:45.236142 | controller | repo_setup : Ensure directories are present ----------------------------- 0.54s
2025-09-30 08:44:45.236147 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.43s
2025-09-30 08:44:45.236153 | controller | Inject crc hostname/IP in hosts ----------------------------------------- 0.31s
2025-09-30 08:44:45.236158 | controller | test_deps : Disable ubi host subscription-manager integration ----------- 0.31s
2025-09-30 08:44:45.236165 | controller | test_deps : Detect mirrors file ----------------------------------------- 0.29s
2025-09-30 08:44:45.236472 | controller | repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist) --- 0.22s
2025-09-30 08:44:45.288645 | controller | repo_setup : Use RDO proxy mirrors -------------------------------------- 0.21s
2025-09-30 08:44:45.288680 | controller | repo_setup : Check for /etc/ci/mirror_info.sh --------------------------- 0.19s
2025-09-30 08:44:45.288687 | controller | repo_setup : Export hashes facts for further use ------------------------ 0.10s
2025-09-30 08:44:45.288698 | controller | INFO     Running default > converge
2025-09-30 08:44:45.742925 | controller |
2025-09-30 08:44:46.602080 | controller | PLAY [Converge] ****************************************************************
2025-09-30 08:44:46.602137 | controller |
2025-09-30 08:44:46.602149 | controller | TASK [Gathering Facts] *********************************************************
2025-09-30 08:44:46.602155 | controller | Tuesday 30 September 2025  08:44:45 +0000 (0:00:00.016)       0:00:00.016 *****
2025-09-30 08:44:46.602165 | controller | ok: [instance]
2025-09-30 08:44:46.602201 | controller |
2025-09-30 08:44:46.602208 | controller | TASK [Load networking_definition] **********************************************
2025-09-30 08:44:46.602216 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.859)       0:00:00.876 *****
2025-09-30 08:44:46.620930 | controller | ok: [instance]
2025-09-30 08:44:46.621022 | controller |
2025-09-30 08:44:46.621051 | controller | TASK [Check if new ssh keypair exists] *****************************************
2025-09-30 08:44:46.621064 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.019)       0:00:00.895 *****
2025-09-30 08:44:46.644699 | controller |
2025-09-30 08:44:46.929940 | controller | TASK [recognize_ssh_keypair : Check if id_ed25519 key exists] ******************
2025-09-30 08:44:46.929970 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.023)       0:00:00.919 *****
2025-09-30 08:44:46.929982 | controller | ok: [instance]
2025-09-30 08:44:46.949876 | controller |
2025-09-30 08:44:46.949909 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair exists] ******************
2025-09-30 08:44:46.949924 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.284)       0:00:01.204 *****
2025-09-30 08:44:46.949934 | controller | ok: [instance]
2025-09-30 08:44:46.949960 | controller |
2025-09-30 08:44:46.950220 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair does not exists] *********
2025-09-30 08:44:46.972521 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.020)       0:00:01.224 *****
2025-09-30 08:44:46.972547 | controller | skipping: [instance]
2025-09-30 08:44:46.996761 | controller |
2025-09-30 08:44:46.996784 | controller | TASK [Add the crc host dynamically] ********************************************
2025-09-30 08:44:46.996793 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.022)       0:00:01.247 *****
2025-09-30 08:44:46.996804 | controller | changed: [instance]
2025-09-30 08:44:47.023087 | controller |
2025-09-30 08:44:47.023147 | controller | TASK [Add ansible_host entry to "controller-0"] ********************************
2025-09-30 08:44:47.023162 | controller | Tuesday 30 September 2025  08:44:46 +0000 (0:00:00.024)       0:00:01.271 *****
2025-09-30 08:44:47.023174 | controller | changed: [instance]
2025-09-30 08:44:47.349051 | controller |
2025-09-30 08:44:47.349081 | controller | TASK [Add host key to controller-0] ********************************************
2025-09-30 08:44:47.349089 | controller | Tuesday 30 September 2025  08:44:47 +0000 (0:00:00.026)       0:00:01.297 *****
2025-09-30 08:44:47.349099 | controller | changed: [instance]
2025-09-30 08:44:47.659236 | controller |
2025-09-30 08:44:47.659276 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-09-30 08:44:47.659285 | controller | Tuesday 30 September 2025  08:44:47 +0000 (0:00:00.325)       0:00:01.623 *****
2025-09-30 08:44:47.659297 | controller | ok: [instance]
2025-09-30 08:44:47.659341 | controller |
2025-09-30 08:44:47.659352 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-09-30 08:44:47.659433 | controller | Tuesday 30 September 2025  08:44:47 +0000 (0:00:00.310)       0:00:01.933 *****
2025-09-30 08:44:47.848367 | controller | changed: [instance]
2025-09-30 08:44:47.848423 | controller |
2025-09-30 08:44:47.848559 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-09-30 08:44:47.848669 | controller | Tuesday 30 September 2025  08:44:47 +0000 (0:00:00.189)       0:00:02.123 *****
2025-09-30 08:44:48.035212 | controller | ok: [instance]
2025-09-30 08:44:48.035538 | controller |
2025-09-30 08:44:48.063572 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-09-30 08:44:48.063601 | controller | Tuesday 30 September 2025  08:44:48 +0000 (0:00:00.186)       0:00:02.309 *****
2025-09-30 08:44:48.063612 | controller | skipping: [instance]
2025-09-30 08:44:48.063865 | controller |
2025-09-30 08:44:48.063893 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-09-30 08:44:48.080180 | controller | Tuesday 30 September 2025  08:44:48 +0000 (0:00:00.028)       0:00:02.338 *****
2025-09-30 08:44:48.080215 | controller | skipping: [instance]
2025-09-30 08:44:48.080253 | controller |
2025-09-30 08:44:48.080262 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-09-30 08:44:48.080372 | controller | Tuesday 30 September 2025  08:44:48 +0000 (0:00:00.016)       0:00:02.354 *****
2025-09-30 08:44:48.099660 | controller | ok: [instance]
2025-09-30 08:44:48.099740 | controller |
2025-09-30 08:44:48.099762 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-09-30 08:44:48.099775 | controller | Tuesday 30 September 2025  08:44:48 +0000 (0:00:00.019)       0:00:02.374 *****
2025-09-30 08:44:48.127874 | controller | skipping: [instance]
2025-09-30 08:44:48.127914 | controller |
2025-09-30 08:44:48.127923 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-09-30 08:44:48.127931 | controller | Tuesday 30 September 2025  08:44:48 +0000 (0:00:00.028)       0:00:02.402 *****
2025-09-30 08:44:59.176204 | controller | changed: [instance]
2025-09-30 08:44:59.176510 | controller |
2025-09-30 08:44:59.393008 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-09-30 08:44:59.393038 | controller | Tuesday 30 September 2025  08:44:59 +0000 (0:00:11.048)       0:00:13.450 *****
2025-09-30 08:44:59.393050 | controller | changed: [instance]
2025-09-30 08:44:59.393084 | controller |
2025-09-30 08:44:59.393342 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-09-30 08:44:59.879518 | controller | Tuesday 30 September 2025  08:44:59 +0000 (0:00:00.216)       0:00:13.667 *****
2025-09-30 08:44:59.879556 | controller | changed: [instance]
2025-09-30 08:44:59.879646 | controller |
2025-09-30 08:44:59.879654 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-09-30 08:44:59.879662 | controller | Tuesday 30 September 2025  08:44:59 +0000 (0:00:00.486)       0:00:14.154 *****
2025-09-30 08:45:00.465701 | controller | changed: [instance]
2025-09-30 08:45:00.465878 | controller |
2025-09-30 08:45:00.465906 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-09-30 08:45:00.465950 | controller | Tuesday 30 September 2025  08:45:00 +0000 (0:00:00.586)       0:00:14.740 *****
2025-09-30 08:45:00.672798 | controller | ok: [instance]
2025-09-30 08:45:00.673178 | controller |
2025-09-30 08:45:01.334438 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-09-30 08:45:01.334473 | controller | Tuesday 30 September 2025  08:45:00 +0000 (0:00:00.207)       0:00:14.947 *****
2025-09-30 08:45:01.334488 | controller | ok: [instance]
2025-09-30 08:45:01.334737 | controller |
2025-09-30 08:45:01.334750 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-09-30 08:45:02.298797 | controller | Tuesday 30 September 2025  08:45:01 +0000 (0:00:00.661)       0:00:15.609 *****
2025-09-30 08:45:02.298841 | controller | changed: [instance]
2025-09-30 08:45:02.383391 | controller |
2025-09-30 08:45:02.383424 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-09-30 08:45:02.383432 | controller | Tuesday 30 September 2025  08:45:02 +0000 (0:00:00.963)       0:00:16.572 *****
2025-09-30 08:45:02.383443 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-09-30 08:45:02.718557 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-09-30 08:45:02.718591 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-09-30 08:45:02.718599 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-09-30 08:45:02.718605 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-09-30 08:45:02.718610 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-09-30 08:45:02.718615 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-09-30 08:45:02.718621 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-09-30 08:45:02.718626 | controller |
2025-09-30 08:45:02.718632 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-09-30 08:45:02.718638 | controller | Tuesday 30 September 2025  08:45:02 +0000 (0:00:00.083)       0:00:16.656 *****
2025-09-30 08:45:02.718647 | controller | ok: [instance]
2025-09-30 08:45:03.057739 | controller |
2025-09-30 08:45:03.057774 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-09-30 08:45:03.057783 | controller | Tuesday 30 September 2025  08:45:02 +0000 (0:00:00.333)       0:00:16.990 *****
2025-09-30 08:45:03.057798 | controller | ok: [instance]
2025-09-30 08:45:03.425093 | controller |
2025-09-30 08:45:03.425145 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-09-30 08:45:03.425155 | controller | Tuesday 30 September 2025  08:45:03 +0000 (0:00:00.341)       0:00:17.331 *****
2025-09-30 08:45:03.425165 | controller | ok: [instance]
2025-09-30 08:45:03.781723 | controller |
2025-09-30 08:45:03.781761 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-09-30 08:45:03.781778 | controller | Tuesday 30 September 2025  08:45:03 +0000 (0:00:00.366)       0:00:17.697 *****
2025-09-30 08:45:03.781788 | controller | ok: [instance]
2025-09-30 08:45:04.150210 | controller |
2025-09-30 08:45:04.150243 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-09-30 08:45:04.150251 | controller | Tuesday 30 September 2025  08:45:03 +0000 (0:00:00.358)       0:00:18.055 *****
2025-09-30 08:45:04.150268 | controller | ok: [instance]
2025-09-30 08:45:04.530520 | controller |
2025-09-30 08:45:04.530558 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-09-30 08:45:04.530566 | controller | Tuesday 30 September 2025  08:45:04 +0000 (0:00:00.368)       0:00:18.424 *****
2025-09-30 08:45:04.530577 | controller | ok: [instance]
2025-09-30 08:45:04.893060 | controller |
2025-09-30 08:45:04.893096 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-09-30 08:45:04.893122 | controller | Tuesday 30 September 2025  08:45:04 +0000 (0:00:00.380)       0:00:18.804 *****
2025-09-30 08:45:04.893137 | controller | ok: [instance]
2025-09-30 08:45:05.270788 | controller |
2025-09-30 08:45:05.270827 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-09-30 08:45:05.270839 | controller | Tuesday 30 September 2025  08:45:04 +0000 (0:00:00.362)       0:00:19.167 *****
2025-09-30 08:45:05.270849 | controller | ok: [instance]
2025-09-30 08:45:05.654397 | controller |
2025-09-30 08:45:05.654435 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-09-30 08:45:05.654443 | controller | Tuesday 30 September 2025  08:45:05 +0000 (0:00:00.376)       0:00:19.544 *****
2025-09-30 08:45:05.654453 | controller | ok: [instance]
2025-09-30 08:45:06.022546 | controller |
2025-09-30 08:45:06.022585 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-09-30 08:45:06.022594 | controller | Tuesday 30 September 2025  08:45:05 +0000 (0:00:00.381)       0:00:19.925 *****
2025-09-30 08:45:06.022604 | controller | ok: [instance]
2025-09-30 08:45:06.383747 | controller |
2025-09-30 08:45:06.383781 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-09-30 08:45:06.383789 | controller | Tuesday 30 September 2025  08:45:06 +0000 (0:00:00.370)       0:00:20.296 *****
2025-09-30 08:45:06.383799 | controller | ok: [instance]
2025-09-30 08:45:06.730910 | controller |
2025-09-30 08:45:06.730950 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-09-30 08:45:06.730966 | controller | Tuesday 30 September 2025  08:45:06 +0000 (0:00:00.361)       0:00:20.657 *****
2025-09-30 08:45:06.730976 | controller | ok: [instance]
2025-09-30 08:45:07.093328 | controller |
2025-09-30 08:45:07.093372 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-09-30 08:45:07.093381 | controller | Tuesday 30 September 2025  08:45:06 +0000 (0:00:00.345)       0:00:21.003 *****
2025-09-30 08:45:07.093391 | controller | ok: [instance]
2025-09-30 08:45:07.434205 | controller |
2025-09-30 08:45:07.434243 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-09-30 08:45:07.434251 | controller | Tuesday 30 September 2025  08:45:07 +0000 (0:00:00.362)       0:00:21.365 *****
2025-09-30 08:45:07.434262 | controller | ok: [instance]
2025-09-30 08:45:07.783965 | controller |
2025-09-30 08:45:07.784006 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-09-30 08:45:07.784015 | controller | Tuesday 30 September 2025  08:45:07 +0000 (0:00:00.343)       0:00:21.708 *****
2025-09-30 08:45:07.784026 | controller | ok: [instance]
2025-09-30 08:45:08.130510 | controller |
2025-09-30 08:45:08.130541 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-09-30 08:45:08.130549 | controller | Tuesday 30 September 2025  08:45:07 +0000 (0:00:00.349)       0:00:22.058 *****
2025-09-30 08:45:08.130559 | controller | ok: [instance]
2025-09-30 08:45:08.130583 | controller |
2025-09-30 08:45:08.130589 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-09-30 08:45:08.130596 | controller | Tuesday 30 September 2025  08:45:08 +0000 (0:00:00.346)       0:00:22.405 *****
2025-09-30 08:45:08.458220 | controller | ok: [instance]
2025-09-30 08:45:08.458436 | controller |
2025-09-30 08:45:08.458452 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-09-30 08:45:08.784014 | controller | Tuesday 30 September 2025  08:45:08 +0000 (0:00:00.327)       0:00:22.732 *****
2025-09-30 08:45:08.784054 | controller | ok: [instance]
2025-09-30 08:45:08.784129 | controller |
2025-09-30 08:45:08.784279 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-09-30 08:45:08.784418 | controller | Tuesday 30 September 2025  08:45:08 +0000 (0:00:00.325)       0:00:23.058 *****
2025-09-30 08:45:09.129860 | controller | ok: [instance]
2025-09-30 08:45:09.129934 | controller |
2025-09-30 08:45:09.130055 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-09-30 08:45:09.130167 | controller | Tuesday 30 September 2025  08:45:09 +0000 (0:00:00.345)       0:00:23.404 *****
2025-09-30 08:45:09.481453 | controller | ok: [instance]
2025-09-30 08:45:09.481557 | controller |
2025-09-30 08:45:09.481675 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-09-30 08:45:09.481780 | controller | Tuesday 30 September 2025  08:45:09 +0000 (0:00:00.351)       0:00:23.756 *****
2025-09-30 08:45:09.891036 | controller | ok: [instance]
2025-09-30 08:45:09.891164 | controller |
2025-09-30 08:45:09.891180 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-09-30 08:45:09.891190 | controller | Tuesday 30 September 2025  08:45:09 +0000 (0:00:00.408)       0:00:24.165 *****
2025-09-30 08:45:10.242389 | controller | ok: [instance]
2025-09-30 08:45:10.242610 | controller |
2025-09-30 08:45:10.242629 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-09-30 08:45:11.594205 | controller | Tuesday 30 September 2025  08:45:10 +0000 (0:00:00.351)       0:00:24.516 *****
2025-09-30 08:45:11.594247 | controller | ok: [instance]
2025-09-30 08:45:11.594258 | controller |
2025-09-30 08:45:11.594389 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-09-30 08:45:11.594498 | controller | Tuesday 30 September 2025  08:45:11 +0000 (0:00:01.351)       0:00:25.868 *****
2025-09-30 08:45:11.923171 | controller | ok: [instance]
2025-09-30 08:45:11.923279 | controller |
2025-09-30 08:45:11.923432 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-09-30 08:45:11.923547 | controller | Tuesday 30 September 2025  08:45:11 +0000 (0:00:00.329)       0:00:26.197 *****
2025-09-30 08:45:11.943582 | controller | skipping: [instance]
2025-09-30 08:45:11.943684 | controller |
2025-09-30 08:45:11.943813 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-09-30 08:45:11.943940 | controller | Tuesday 30 September 2025  08:45:11 +0000 (0:00:00.020)       0:00:26.218 *****
2025-09-30 08:45:12.226862 | controller | ok: [instance]
2025-09-30 08:45:12.226955 | controller |
2025-09-30 08:45:12.227498 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-09-30 08:45:12.618958 | controller | Tuesday 30 September 2025  08:45:12 +0000 (0:00:00.283)       0:00:26.501 *****
2025-09-30 08:45:12.619005 | controller | ok: [instance]
2025-09-30 08:45:12.619058 | controller |
2025-09-30 08:45:12.619206 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-09-30 08:45:12.619314 | controller | Tuesday 30 September 2025  08:45:12 +0000 (0:00:00.392)       0:00:26.893 *****
2025-09-30 08:45:12.931535 | controller | changed: [instance]
2025-09-30 08:45:12.931612 | controller |
2025-09-30 08:45:12.931722 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-09-30 08:45:12.931827 | controller | Tuesday 30 September 2025  08:45:12 +0000 (0:00:00.312)       0:00:27.206 *****
2025-09-30 08:45:13.222352 | controller | [WARNING]: Reset is not implemented for this connection
2025-09-30 08:45:13.232979 | controller | changed: [instance]
2025-09-30 08:45:13.233080 | controller |
2025-09-30 08:45:13.233221 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-09-30 08:45:13.233334 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.285)       0:00:27.491 *****
2025-09-30 08:45:13.233459 | controller |
2025-09-30 08:45:13.233548 | controller | TASK [Create virtual baremetal VMs] ********************************************
2025-09-30 08:45:13.233651 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.016)       0:00:27.507 *****
2025-09-30 08:45:13.301599 | controller |
2025-09-30 08:45:13.301705 | controller | TASK [libvirt_manager : Import layout generator if needed] *********************
2025-09-30 08:45:13.301824 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.068)       0:00:27.576 *****
2025-09-30 08:45:13.331038 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_layout.yml for instance
2025-09-30 08:45:13.331172 | controller |
2025-09-30 08:45:13.331298 | controller | TASK [libvirt_manager : Chose right parameter for layout definition] ***********
2025-09-30 08:45:13.331446 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.029)       0:00:27.605 *****
2025-09-30 08:45:13.361112 | controller | ok: [instance]
2025-09-30 08:45:13.361233 | controller |
2025-09-30 08:45:13.361386 | controller | TASK [libvirt_manager : Patch the layout if needed] ****************************
2025-09-30 08:45:13.361516 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.030)       0:00:27.636 *****
2025-09-30 08:45:13.436020 | controller | skipping: [instance]
2025-09-30 08:45:13.436149 | controller |
2025-09-30 08:45:13.436252 | controller | TASK [libvirt_manager : Enable forwarding in the libvirt zone] *****************
2025-09-30 08:45:13.436375 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.072)       0:00:27.709 *****
2025-09-30 08:45:13.862503 | controller | changed: [instance]
2025-09-30 08:45:13.862584 | controller |
2025-09-30 08:45:13.862811 | controller | TASK [libvirt_manager : Enable masquerading for public traffic] ****************
2025-09-30 08:45:14.362070 | controller | Tuesday 30 September 2025  08:45:13 +0000 (0:00:00.428)       0:00:28.137 *****
2025-09-30 08:45:14.362130 | controller | changed: [instance]
2025-09-30 08:45:14.362192 | controller |
2025-09-30 08:45:14.362206 | controller | TASK [libvirt_manager : Ensure firewalld is restarts] **************************
2025-09-30 08:45:14.362212 | controller | Tuesday 30 September 2025  08:45:14 +0000 (0:00:00.489)       0:00:28.627 *****
2025-09-30 08:45:14.362217 | controller |
2025-09-30 08:45:14.362222 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-09-30 08:45:14.362230 | controller | Tuesday 30 September 2025  08:45:14 +0000 (0:00:00.009)       0:00:28.636 *****
2025-09-30 08:45:15.166562 | controller | changed: [instance]
2025-09-30 08:45:15.166598 | controller |
2025-09-30 08:45:15.166682 | controller | TASK [Deploy virtualbmc] *******************************************************
2025-09-30 08:45:15.166785 | controller | Tuesday 30 September 2025  08:45:15 +0000 (0:00:00.804)       0:00:29.441 *****
2025-09-30 08:45:15.196544 | controller | skipping: [instance]
2025-09-30 08:45:15.196679 | controller |
2025-09-30 08:45:15.196752 | controller | TASK [libvirt_manager : Let the project know we have vbmc available] ***********
2025-09-30 08:45:15.196847 | controller | Tuesday 30 September 2025  08:45:15 +0000 (0:00:00.029)       0:00:29.470 *****
2025-09-30 08:45:15.227111 | controller | skipping: [instance]
2025-09-30 08:45:15.227154 | controller |
2025-09-30 08:45:15.227258 | controller | TASK [libvirt_manager : Create needed workload directory] **********************
2025-09-30 08:45:15.227393 | controller | Tuesday 30 September 2025  08:45:15 +0000 (0:00:00.030)       0:00:29.501 *****
2025-09-30 08:45:15.805237 | controller | changed: [instance] => (item=workload)
2025-09-30 08:45:15.805398 | controller | changed: [instance] => (item=reproducer-inventory)
2025-09-30 08:45:15.805468 | controller | changed: [instance] => (item=volumes)
2025-09-30 08:45:15.805561 | controller |
2025-09-30 08:45:15.805668 | controller | TASK [libvirt_manager : Allow QEMU on workload directory] **********************
2025-09-30 08:45:15.805762 | controller | Tuesday 30 September 2025  08:45:15 +0000 (0:00:00.578)       0:00:30.080 *****
2025-09-30 08:45:16.223075 | controller | changed: [instance] => (item=workload)
2025-09-30 08:45:16.223128 | controller | changed: [instance] => (item=volumes)
2025-09-30 08:45:16.223238 | controller |
2025-09-30 08:45:16.223436 | controller | TASK [libvirt_manager : Generate networking data] ******************************
2025-09-30 08:45:16.300067 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.417)       0:00:30.497 *****
2025-09-30 08:45:16.300124 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_networking_data.yml for instance
2025-09-30 08:45:16.300255 | controller |
2025-09-30 08:45:16.300403 | controller | TASK [libvirt_manager : Ensure fact is existing, and empty] ********************
2025-09-30 08:45:16.300523 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.076)       0:00:30.574 *****
2025-09-30 08:45:16.318529 | controller | ok: [instance]
2025-09-30 08:45:16.318606 | controller |
2025-09-30 08:45:16.318709 | controller | TASK [libvirt_manager : Check if we get an existing interfaces-info.yml] *******
2025-09-30 08:45:16.318807 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.018)       0:00:30.593 *****
2025-09-30 08:45:16.507541 | controller | ok: [instance]
2025-09-30 08:45:16.507594 | controller |
2025-09-30 08:45:16.507756 | controller | TASK [libvirt_manager : Load file if exists] ***********************************
2025-09-30 08:45:16.507858 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.188)       0:00:30.781 *****
2025-09-30 08:45:16.537186 | controller | skipping: [instance]
2025-09-30 08:45:16.564498 | controller |
2025-09-30 08:45:16.564555 | controller | TASK [libvirt_manager : Update fact with existing content] *********************
2025-09-30 08:45:16.564564 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.028)       0:00:30.810 *****
2025-09-30 08:45:16.564579 | controller | skipping: [instance]
2025-09-30 08:45:16.564661 | controller |
2025-09-30 08:45:16.564672 | controller | TASK [libvirt_manager : Generate VM list] **************************************
2025-09-30 08:45:16.564762 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.028)       0:00:30.839 *****
2025-09-30 08:45:16.612834 | controller | ok: [instance]
2025-09-30 08:45:16.612886 | controller |
2025-09-30 08:45:16.612984 | controller | TASK [libvirt_manager : Generate/update mapping all nodes] *********************
2025-09-30 08:45:16.613078 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.048)       0:00:30.887 *****
2025-09-30 08:45:16.708027 | controller | ok: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-09-30 08:45:16.708086 | controller | ok: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-09-30 08:45:16.708264 | controller |
2025-09-30 08:45:16.708413 | controller | TASK [libvirt_manager : Append baremetal nodes if needed] **********************
2025-09-30 08:45:16.708530 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.095)       0:00:30.982 *****
2025-09-30 08:45:16.740858 | controller | skipping: [instance]
2025-09-30 08:45:16.740917 | controller |
2025-09-30 08:45:16.741045 | controller | TASK [libvirt_manager : Dump MAC mapping] **************************************
2025-09-30 08:45:16.741156 | controller | Tuesday 30 September 2025  08:45:16 +0000 (0:00:00.033)       0:00:31.015 *****
2025-09-30 08:45:17.086476 | controller | changed: [instance]
2025-09-30 08:45:17.086544 | controller |
2025-09-30 08:45:17.086648 | controller | TASK [libvirt_manager : Inject all VMs in the inventory] ***********************
2025-09-30 08:45:17.086752 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.345)       0:00:31.361 *****
2025-09-30 08:45:17.175671 | controller | changed: [instance] => (item=Adding compute-0 to computes)
2025-09-30 08:45:17.175743 | controller | changed: [instance] => (item=Adding compute-1 to computes)
2025-09-30 08:45:17.175848 | controller |
2025-09-30 08:45:17.175961 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-09-30 08:45:17.176075 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.089)       0:00:31.450 *****
2025-09-30 08:45:17.198854 | controller | skipping: [instance]
2025-09-30 08:45:17.198934 | controller |
2025-09-30 08:45:17.199044 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-09-30 08:45:17.199187 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.023)       0:00:31.473 *****
2025-09-30 08:45:17.223430 | controller | skipping: [instance]
2025-09-30 08:45:17.223528 | controller |
2025-09-30 08:45:17.223970 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-09-30 08:45:17.223995 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.024)       0:00:31.498 *****
2025-09-30 08:45:17.249706 | controller | skipping: [instance]
2025-09-30 08:45:17.249777 | controller |
2025-09-30 08:45:17.249881 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-09-30 08:45:17.249983 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.026)       0:00:31.524 *****
2025-09-30 08:45:17.274199 | controller | skipping: [instance]
2025-09-30 08:45:17.274259 | controller |
2025-09-30 08:45:17.274395 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-09-30 08:45:17.274566 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.024)       0:00:31.549 *****
2025-09-30 08:45:17.293226 | controller | ok: [instance]
2025-09-30 08:45:17.293305 | controller |
2025-09-30 08:45:17.293421 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-09-30 08:45:17.293514 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.019)       0:00:31.568 *****
2025-09-30 08:45:17.361893 | 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': {}}}}})
2025-09-30 08:45:17.361960 | controller |
2025-09-30 08:45:17.362066 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-09-30 08:45:17.362185 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.068)       0:00:31.636 *****
2025-09-30 08:45:17.379201 | controller | skipping: [instance]
2025-09-30 08:45:17.379288 | controller |
2025-09-30 08:45:17.379419 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-09-30 08:45:17.379518 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.017)       0:00:31.654 *****
2025-09-30 08:45:17.582597 | controller | changed: [instance]
2025-09-30 08:45:17.582675 | controller |
2025-09-30 08:45:17.582784 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-09-30 08:45:17.582887 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.203)       0:00:31.857 *****
2025-09-30 08:45:17.983805 | controller | changed: [instance]
2025-09-30 08:45:17.983876 | controller |
2025-09-30 08:45:17.983990 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-09-30 08:45:17.984095 | controller | Tuesday 30 September 2025  08:45:17 +0000 (0:00:00.400)       0:00:32.258 *****
2025-09-30 08:45:18.032253 | controller | ok: [instance]
2025-09-30 08:45:18.032324 | controller |
2025-09-30 08:45:18.032445 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-09-30 08:45:18.032619 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.048)       0:00:32.307 *****
2025-09-30 08:45:18.054740 | controller | ok: [instance]
2025-09-30 08:45:18.449621 | controller |
2025-09-30 08:45:18.449662 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-09-30 08:45:18.449671 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.022)       0:00:32.329 *****
2025-09-30 08:45:18.449685 | controller | changed: [instance]
2025-09-30 08:45:18.541993 | controller |
2025-09-30 08:45:18.542030 | controller | TASK [libvirt_manager : Manage networks if needed] *****************************
2025-09-30 08:45:18.542039 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.394)       0:00:32.724 *****
2025-09-30 08:45:18.542051 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks.yml for instance
2025-09-30 08:45:18.582437 | controller |
2025-09-30 08:45:18.582467 | controller | TASK [libvirt_manager : Define the localized variables for performing the tasks here.] ***
2025-09-30 08:45:18.582476 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.092)       0:00:32.816 *****
2025-09-30 08:45:18.582488 | controller | ok: [instance] => (item=public)
2025-09-30 08:45:18.928216 | controller |
2025-09-30 08:45:18.928268 | controller | TASK [libvirt_manager : Ensure networks are defined] ***************************
2025-09-30 08:45:18.928277 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.040)       0:00:32.856 *****
2025-09-30 08:45:18.928290 | controller | changed: [instance] => (item=cifmw-public)
2025-09-30 08:45:19.272324 | controller |
2025-09-30 08:45:19.272377 | controller | TASK [libvirt_manager : Ensure networks are created/started] *******************
2025-09-30 08:45:19.272386 | controller | Tuesday 30 September 2025  08:45:18 +0000 (0:00:00.345)       0:00:33.202 *****
2025-09-30 08:45:19.272400 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:19.542828 | controller |
2025-09-30 08:45:19.542863 | controller | TASK [libvirt_manager : Ensure networks are active] ****************************
2025-09-30 08:45:19.542878 | controller | Tuesday 30 September 2025  08:45:19 +0000 (0:00:00.343)       0:00:33.545 *****
2025-09-30 08:45:19.542890 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:19.787727 | controller |
2025-09-30 08:45:19.787761 | controller | TASK [libvirt_manager : Ensure networks enabled to autostart] ******************
2025-09-30 08:45:19.787770 | controller | Tuesday 30 September 2025  08:45:19 +0000 (0:00:00.271)       0:00:33.816 *****
2025-09-30 08:45:19.787781 | controller | changed: [instance] => (item=cifmw-public)
2025-09-30 08:45:19.845377 | controller |
2025-09-30 08:45:19.845414 | controller | TASK [libvirt_manager : Add a dummy interface to bridges if required] **********
2025-09-30 08:45:19.845433 | controller | Tuesday 30 September 2025  08:45:19 +0000 (0:00:00.245)       0:00:34.062 *****
2025-09-30 08:45:19.845446 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks_dummy_interfaces.yml for instance
2025-09-30 08:45:20.039914 | controller |
2025-09-30 08:45:20.039952 | controller | TASK [libvirt_manager : Fetch present bridge interfaces] ***********************
2025-09-30 08:45:20.039960 | controller | Tuesday 30 September 2025  08:45:19 +0000 (0:00:00.057)       0:00:34.119 *****
2025-09-30 08:45:20.039970 | controller | ok: [instance]
2025-09-30 08:45:20.039987 | controller |
2025-09-30 08:45:20.039993 | controller | TASK [libvirt_manager : Fetch bridges ports link info] *************************
2025-09-30 08:45:20.040000 | controller | Tuesday 30 September 2025  08:45:20 +0000 (0:00:00.194)       0:00:34.314 *****
2025-09-30 08:45:20.260895 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:20.260949 | controller |
2025-09-30 08:45:20.261080 | controller | TASK [Create dummy interfaces to ensure bridges are UP] ************************
2025-09-30 08:45:20.261205 | controller | Tuesday 30 September 2025  08:45:20 +0000 (0:00:00.221)       0:00:34.535 *****
2025-09-30 08:45:20.330345 | controller |
2025-09-30 08:45:20.330464 | controller | TASK [ci_nmstate : Ensure we have needed facts] ********************************
2025-09-30 08:45:20.330571 | controller | Tuesday 30 September 2025  08:45:20 +0000 (0:00:00.069)       0:00:34.604 *****
2025-09-30 08:45:20.368124 | controller | skipping: [instance]
2025-09-30 08:45:20.368221 | controller |
2025-09-30 08:45:20.368331 | controller | TASK [ci_nmstate : Install required packages on instance] **********************
2025-09-30 08:45:20.368446 | controller | Tuesday 30 September 2025  08:45:20 +0000 (0:00:00.038)       0:00:34.642 *****
2025-09-30 08:45:26.026483 | controller | changed: [instance]
2025-09-30 08:45:26.026535 | controller |
2025-09-30 08:45:26.026545 | controller | TASK [ci_nmstate : Create the target NMstate dump directory] *******************
2025-09-30 08:45:26.026600 | controller | Tuesday 30 September 2025  08:45:26 +0000 (0:00:05.657)       0:00:40.300 *****
2025-09-30 08:45:26.235675 | controller | changed: [instance]
2025-09-30 08:45:26.235757 | controller |
2025-09-30 08:45:26.235870 | controller | TASK [ci_nmstate : Save nmstate state for instance] ****************************
2025-09-30 08:45:26.235977 | controller | Tuesday 30 September 2025  08:45:26 +0000 (0:00:00.209)       0:00:40.510 *****
2025-09-30 08:45:26.602294 | controller | changed: [instance]
2025-09-30 08:45:26.602430 | controller |
2025-09-30 08:45:26.602486 | controller | TASK [ci_nmstate : Apply the desidered state on instance] **********************
2025-09-30 08:45:26.602591 | controller | Tuesday 30 September 2025  08:45:26 +0000 (0:00:00.366)       0:00:40.876 *****
2025-09-30 08:45:28.513409 | controller | changed: [instance]
2025-09-30 08:45:28.513468 | controller |
2025-09-30 08:45:28.513692 | controller | TASK [ci_nmstate : Save nmstate debugging data for instance] *******************
2025-09-30 08:45:28.876978 | controller | Tuesday 30 September 2025  08:45:28 +0000 (0:00:01.911)       0:00:42.787 *****
2025-09-30 08:45:28.877014 | controller | changed: [instance]
2025-09-30 08:45:28.909035 | controller |
2025-09-30 08:45:28.909064 | controller | TASK [Create extra network configuration] **************************************
2025-09-30 08:45:28.909073 | controller | Tuesday 30 September 2025  08:45:28 +0000 (0:00:00.363)       0:00:43.151 *****
2025-09-30 08:45:28.909083 | controller | skipping: [instance]
2025-09-30 08:45:28.941641 | controller |
2025-09-30 08:45:28.941668 | controller | TASK [libvirt_manager : Ensure extra networks is in correct zone] **************
2025-09-30 08:45:28.941676 | controller | Tuesday 30 September 2025  08:45:28 +0000 (0:00:00.032)       0:00:43.183 *****
2025-09-30 08:45:28.941693 | controller | skipping: [instance]
2025-09-30 08:45:29.390401 | controller |
2025-09-30 08:45:29.390438 | controller | TASK [libvirt_manager : Refresh networking facts on host] **********************
2025-09-30 08:45:29.390448 | controller | Tuesday 30 September 2025  08:45:28 +0000 (0:00:00.032)       0:00:43.216 *****
2025-09-30 08:45:29.390461 | controller | ok: [instance]
2025-09-30 08:45:29.390787 | controller |
2025-09-30 08:45:29.509940 | controller | TASK [libvirt_manager : Build needed network/dnsmasq related content] **********
2025-09-30 08:45:29.509974 | controller | Tuesday 30 September 2025  08:45:29 +0000 (0:00:00.448)       0:00:43.665 *****
2025-09-30 08:45:29.509986 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:30.759506 | controller |
2025-09-30 08:45:30.759543 | controller | TASK [dnsmasq : Install needed packages] ***************************************
2025-09-30 08:45:30.759551 | controller | Tuesday 30 September 2025  08:45:29 +0000 (0:00:00.119)       0:00:43.784 *****
2025-09-30 08:45:30.759563 | controller | ok: [instance]
2025-09-30 08:45:30.759587 | controller |
2025-09-30 08:45:30.759593 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ******
2025-09-30 08:45:30.759601 | controller | Tuesday 30 September 2025  08:45:30 +0000 (0:00:01.249)       0:00:45.033 *****
2025-09-30 08:45:34.554801 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'})
2025-09-30 08:45:34.555030 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'})
2025-09-30 08:45:34.555147 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'})
2025-09-30 08:45:34.555163 | controller |
2025-09-30 08:45:34.555329 | controller | TASK [dnsmasq : Manage configuration directory] ********************************
2025-09-30 08:45:34.778286 | controller | Tuesday 30 September 2025  08:45:34 +0000 (0:00:03.795)       0:00:48.829 *****
2025-09-30 08:45:34.778338 | controller | changed: [instance]
2025-09-30 08:45:35.161719 | controller |
2025-09-30 08:45:35.161774 | controller | TASK [dnsmasq : Manage systemd unit file] **************************************
2025-09-30 08:45:35.161784 | controller | Tuesday 30 September 2025  08:45:34 +0000 (0:00:00.223)       0:00:49.052 *****
2025-09-30 08:45:35.161795 | controller | changed: [instance]
2025-09-30 08:45:35.554370 | controller |
2025-09-30 08:45:35.554409 | controller | TASK [dnsmasq : Manage base configuration file] ********************************
2025-09-30 08:45:35.554426 | controller | Tuesday 30 September 2025  08:45:35 +0000 (0:00:00.383)       0:00:49.436 *****
2025-09-30 08:45:35.554438 | controller | changed: [instance]
2025-09-30 08:45:35.554476 | controller |
2025-09-30 08:45:35.554854 | controller | TASK [dnsmasq : Render listener configuration] *********************************
2025-09-30 08:45:35.584455 | controller | Tuesday 30 September 2025  08:45:35 +0000 (0:00:00.393)       0:00:49.829 *****
2025-09-30 08:45:35.584492 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance
2025-09-30 08:45:35.584635 | controller |
2025-09-30 08:45:35.584679 | controller | TASK [dnsmasq : Create listener configuration file] ****************************
2025-09-30 08:45:35.584862 | controller | Tuesday 30 September 2025  08:45:35 +0000 (0:00:00.030)       0:00:49.859 *****
2025-09-30 08:45:35.986486 | controller | changed: [instance]
2025-09-30 08:45:35.986541 | controller |
2025-09-30 08:45:35.986628 | controller | TASK [dnsmasq : Remove listener configuration file] ****************************
2025-09-30 08:45:35.986728 | controller | Tuesday 30 September 2025  08:45:35 +0000 (0:00:00.402)       0:00:50.261 *****
2025-09-30 08:45:36.006250 | controller | skipping: [instance]
2025-09-30 08:45:36.006435 | controller |
2025-09-30 08:45:36.006738 | controller | TASK [dnsmasq : Render dns configuration] **************************************
2025-09-30 08:45:36.006850 | controller | Tuesday 30 September 2025  08:45:36 +0000 (0:00:00.019)       0:00:50.281 *****
2025-09-30 08:45:36.036977 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance
2025-09-30 08:45:36.037062 | controller |
2025-09-30 08:45:36.037198 | controller | TASK [dnsmasq : Create dns configuration file] *********************************
2025-09-30 08:45:36.037316 | controller | Tuesday 30 September 2025  08:45:36 +0000 (0:00:00.030)       0:00:50.312 *****
2025-09-30 08:45:36.418098 | controller | changed: [instance]
2025-09-30 08:45:36.418171 | controller |
2025-09-30 08:45:36.418268 | controller | TASK [dnsmasq : Remove dns configuration file] *********************************
2025-09-30 08:45:36.418389 | controller | Tuesday 30 September 2025  08:45:36 +0000 (0:00:00.380)       0:00:50.692 *****
2025-09-30 08:45:36.437763 | controller | skipping: [instance]
2025-09-30 08:45:36.437838 | controller |
2025-09-30 08:45:36.437945 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] ***
2025-09-30 08:45:36.438044 | controller | Tuesday 30 September 2025  08:45:36 +0000 (0:00:00.020)       0:00:50.712 *****
2025-09-30 08:45:36.665784 | controller | ok: [instance] => (item=127.0.0.2)
2025-09-30 08:45:36.666058 | controller |
2025-09-30 08:45:36.666087 | controller | TASK [dnsmasq : Enable and start service] **************************************
2025-09-30 08:45:36.666097 | controller | Tuesday 30 September 2025  08:45:36 +0000 (0:00:00.227)       0:00:50.940 *****
2025-09-30 08:45:37.372589 | controller | changed: [instance]
2025-09-30 08:45:37.372627 | controller |
2025-09-30 08:45:37.372701 | controller | TASK [dnsmasq : Stop service] **************************************************
2025-09-30 08:45:37.372808 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.706)       0:00:51.647 *****
2025-09-30 08:45:37.391825 | controller | skipping: [instance]
2025-09-30 08:45:37.391932 | controller |
2025-09-30 08:45:37.392031 | controller | TASK [dnsmasq : Remove unit file] **********************************************
2025-09-30 08:45:37.392128 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.019)       0:00:51.666 *****
2025-09-30 08:45:37.410525 | controller | skipping: [instance]
2025-09-30 08:45:37.410608 | controller |
2025-09-30 08:45:37.410731 | controller | TASK [dnsmasq : Remove main configuration files] *******************************
2025-09-30 08:45:37.410852 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.018)       0:00:51.685 *****
2025-09-30 08:45:37.438863 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.conf)
2025-09-30 08:45:37.438973 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.d)
2025-09-30 08:45:37.439126 | controller | skipping: [instance]
2025-09-30 08:45:37.439239 | controller |
2025-09-30 08:45:37.439373 | controller | TASK [Create dnsmasq networks] *************************************************
2025-09-30 08:45:37.439525 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.028)       0:00:51.713 *****
2025-09-30 08:45:37.515127 | controller |
2025-09-30 08:45:37.515236 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************
2025-09-30 08:45:37.515386 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.075)       0:00:51.789 *****
2025-09-30 08:45:37.544317 | controller | ok: [instance] => changed=false
2025-09-30 08:45:37.544447 | controller |   msg: All assertions passed
2025-09-30 08:45:37.544550 | controller |
2025-09-30 08:45:37.544662 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] *******************
2025-09-30 08:45:37.544786 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.029)       0:00:51.819 *****
2025-09-30 08:45:37.582645 | controller | ok: [instance] => changed=false
2025-09-30 08:45:37.582700 | controller |   msg: All assertions passed
2025-09-30 08:45:37.582804 | controller |
2025-09-30 08:45:37.582898 | controller | TASK [dnsmasq : Create network] ************************************************
2025-09-30 08:45:37.582996 | controller | Tuesday 30 September 2025  08:45:37 +0000 (0:00:00.038)       0:00:51.857 *****
2025-09-30 08:45:38.047802 | controller | changed: [instance]
2025-09-30 08:45:38.047840 | controller |
2025-09-30 08:45:38.047972 | controller | TASK [dnsmasq : Remove network] ************************************************
2025-09-30 08:45:38.048071 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.464)       0:00:52.322 *****
2025-09-30 08:45:38.066678 | controller | skipping: [instance]
2025-09-30 08:45:38.066769 | controller |
2025-09-30 08:45:38.066865 | controller | TASK [dnsmasq : Remove dhcp host files] ****************************************
2025-09-30 08:45:38.066976 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.019)       0:00:52.341 *****
2025-09-30 08:45:38.089950 | controller | skipping: [instance]
2025-09-30 08:45:38.090163 | controller |
2025-09-30 08:45:38.090254 | controller | TASK [libvirt_manager : Ensure network is in correct zone] *********************
2025-09-30 08:45:38.090275 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.023)       0:00:52.364 *****
2025-09-30 08:45:38.420752 | controller | changed: [instance] => (item=cifmw-public)
2025-09-30 08:45:38.420806 | controller |
2025-09-30 08:45:38.420931 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-09-30 08:45:38.421046 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.330)       0:00:52.695 *****
2025-09-30 08:45:38.450737 | 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)
2025-09-30 08:45:38.450815 | controller |
2025-09-30 08:45:38.450932 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-09-30 08:45:38.451037 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.030)       0:00:52.725 *****
2025-09-30 08:45:38.762145 | controller | ok: [instance]
2025-09-30 08:45:38.762820 | controller |
2025-09-30 08:45:38.796125 | controller | TASK [libvirt_manager : Set network_bridge_info fact with network and address] ***
2025-09-30 08:45:38.796166 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.311)       0:00:53.036 *****
2025-09-30 08:45:38.796181 | controller | ok: [instance]
2025-09-30 08:45:39.150629 | controller |
2025-09-30 08:45:39.150719 | controller | TASK [libvirt_manager : Output _network_data] **********************************
2025-09-30 08:45:39.150730 | controller | Tuesday 30 September 2025  08:45:38 +0000 (0:00:00.033)       0:00:53.070 *****
2025-09-30 08:45:39.150745 | controller | changed: [instance]
2025-09-30 08:45:39.150852 | controller |
2025-09-30 08:45:39.150865 | controller | TASK [libvirt_manager : Output pub_net] ****************************************
2025-09-30 08:45:39.150876 | controller | Tuesday 30 September 2025  08:45:39 +0000 (0:00:00.354)       0:00:53.425 *****
2025-09-30 08:45:39.500232 | controller | changed: [instance]
2025-09-30 08:45:39.500287 | controller |
2025-09-30 08:45:39.500417 | controller | TASK [libvirt_manager : Output _cifmw_libvirt_manager_layout] ******************
2025-09-30 08:45:39.500521 | controller | Tuesday 30 September 2025  08:45:39 +0000 (0:00:00.349)       0:00:53.775 *****
2025-09-30 08:45:39.839371 | controller | changed: [instance]
2025-09-30 08:45:39.839497 | controller |
2025-09-30 08:45:39.839562 | controller | TASK [libvirt_manager : Expose patch for networking_mapper] ********************
2025-09-30 08:45:39.839661 | controller | Tuesday 30 September 2025  08:45:39 +0000 (0:00:00.339)       0:00:54.114 *****
2025-09-30 08:45:39.958071 | controller | ok: [instance]
2025-09-30 08:45:39.958131 | controller |
2025-09-30 08:45:39.958251 | controller | TASK [libvirt_manager : Save networking_mapper patch] **************************
2025-09-30 08:45:39.958384 | controller | Tuesday 30 September 2025  08:45:39 +0000 (0:00:00.118)       0:00:54.232 *****
2025-09-30 08:45:40.328282 | controller | changed: [instance]
2025-09-30 08:45:40.328325 | controller |
2025-09-30 08:45:40.328481 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-09-30 08:45:40.328572 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.370)       0:00:54.603 *****
2025-09-30 08:45:40.354892 | controller | skipping: [instance]
2025-09-30 08:45:40.354977 | controller |
2025-09-30 08:45:40.355218 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-09-30 08:45:40.377982 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.026)       0:00:54.629 *****
2025-09-30 08:45:40.378010 | controller | skipping: [instance]
2025-09-30 08:45:40.378083 | controller |
2025-09-30 08:45:40.378207 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-09-30 08:45:40.378315 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.023)       0:00:54.653 *****
2025-09-30 08:45:40.401260 | controller | skipping: [instance]
2025-09-30 08:45:40.401381 | controller |
2025-09-30 08:45:40.401513 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-09-30 08:45:40.401605 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.023)       0:00:54.676 *****
2025-09-30 08:45:40.425120 | controller | skipping: [instance]
2025-09-30 08:45:40.425215 | controller |
2025-09-30 08:45:40.425319 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-09-30 08:45:40.425442 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.023)       0:00:54.700 *****
2025-09-30 08:45:40.444185 | controller | ok: [instance]
2025-09-30 08:45:40.444266 | controller |
2025-09-30 08:45:40.444385 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-09-30 08:45:40.444493 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.019)       0:00:54.719 *****
2025-09-30 08:45:40.522256 | 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': {}}}}})
2025-09-30 08:45:40.522368 | controller | ok: [instance] => (item={'networks': {'public': {'network-v4': '192.168.100.0/24'}}, 'group-templates': {'computes': {'networks': {'public': None}}}})
2025-09-30 08:45:40.522453 | controller |
2025-09-30 08:45:40.522559 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-09-30 08:45:40.522667 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.077)       0:00:54.796 *****
2025-09-30 08:45:40.541014 | controller | skipping: [instance]
2025-09-30 08:45:40.541137 | controller |
2025-09-30 08:45:40.541261 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-09-30 08:45:40.541395 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.018)       0:00:54.815 *****
2025-09-30 08:45:40.761696 | controller | ok: [instance]
2025-09-30 08:45:40.761756 | controller |
2025-09-30 08:45:40.761882 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-09-30 08:45:40.761991 | controller | Tuesday 30 September 2025  08:45:40 +0000 (0:00:00.220)       0:00:55.036 *****
2025-09-30 08:45:41.160366 | controller | changed: [instance]
2025-09-30 08:45:41.160935 | controller |
2025-09-30 08:45:41.212710 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-09-30 08:45:41.212736 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.398)       0:00:55.435 *****
2025-09-30 08:45:41.212749 | controller | ok: [instance]
2025-09-30 08:45:41.212803 | controller |
2025-09-30 08:45:41.212905 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-09-30 08:45:41.213020 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.052)       0:00:55.487 *****
2025-09-30 08:45:41.236237 | controller | ok: [instance]
2025-09-30 08:45:41.236312 | controller |
2025-09-30 08:45:41.236451 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-09-30 08:45:41.236566 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.023)       0:00:55.511 *****
2025-09-30 08:45:41.661396 | controller | changed: [instance]
2025-09-30 08:45:41.661443 | controller |
2025-09-30 08:45:41.661576 | controller | TASK [libvirt_manager : Be sure to save current state of networking_mapper environment] ***
2025-09-30 08:45:41.661678 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.424)       0:00:55.936 *****
2025-09-30 08:45:41.683479 | controller | ok: [instance]
2025-09-30 08:45:41.683553 | controller |
2025-09-30 08:45:41.683652 | controller | TASK [libvirt_manager : Unset patch] *******************************************
2025-09-30 08:45:41.683753 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.022)       0:00:55.958 *****
2025-09-30 08:45:41.701973 | controller | ok: [instance]
2025-09-30 08:45:41.702050 | controller |
2025-09-30 08:45:41.702160 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_entries fact] ****************
2025-09-30 08:45:41.702280 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.018)       0:00:55.976 *****
2025-09-30 08:45:41.720587 | controller | ok: [instance]
2025-09-30 08:45:41.720669 | controller |
2025-09-30 08:45:41.720771 | controller | TASK [libvirt_manager : Reserve IPs on networks] *******************************
2025-09-30 08:45:41.720917 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.018)       0:00:55.995 *****
2025-09-30 08:45:41.768067 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=ctlplane)
2025-09-30 08:45:41.768124 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=public)
2025-09-30 08:45:41.768231 | controller |
2025-09-30 08:45:41.768327 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-09-30 08:45:41.768473 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.047)       0:00:56.043 *****
2025-09-30 08:45:41.836703 | controller | skipping: [instance] => (item=compute-0 - ctlplane)
2025-09-30 08:45:41.836792 | controller | skipping: [instance] => (item=compute-1 - ctlplane)
2025-09-30 08:45:41.836905 | controller | skipping: [instance]
2025-09-30 08:45:41.836994 | controller |
2025-09-30 08:45:41.837095 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-09-30 08:45:41.837214 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.068)       0:00:56.111 *****
2025-09-30 08:45:41.932604 | controller | ok: [instance] => (item=compute-0 - public)
2025-09-30 08:45:41.932706 | controller | ok: [instance] => (item=compute-1 - public)
2025-09-30 08:45:41.932761 | controller |
2025-09-30 08:45:41.932891 | controller | TASK [Inject DHCP entries for net {{ net_name }}] ******************************
2025-09-30 08:45:41.932970 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.095)       0:00:56.207 *****
2025-09-30 08:45:41.986662 | controller |
2025-09-30 08:45:41.986740 | controller | TASK [dnsmasq : Ensure we have the right data and type] ************************
2025-09-30 08:45:41.986846 | controller | Tuesday 30 September 2025  08:45:41 +0000 (0:00:00.053)       0:00:56.261 *****
2025-09-30 08:45:42.022358 | controller | ok: [instance]
2025-09-30 08:45:42.022443 | controller |
2025-09-30 08:45:42.022535 | controller | TASK [dnsmasq : Assert we have needed host data] *******************************
2025-09-30 08:45:42.022652 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.035)       0:00:56.297 *****
2025-09-30 08:45:42.074505 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:eb:ec:27', 'ips': ['192.168.100.10', '']})
2025-09-30 08:45:42.074580 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:f4:0e:14', 'ips': ['192.168.100.11', '']})
2025-09-30 08:45:42.074695 | controller |
2025-09-30 08:45:42.074797 | controller | TASK [dnsmasq : Ensure networks exists] ****************************************
2025-09-30 08:45:42.074890 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.052)       0:00:56.349 *****
2025-09-30 08:45:42.116493 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/_check_net_status.yml for instance => (item=public)
2025-09-30 08:45:42.116572 | controller |
2025-09-30 08:45:42.116688 | controller | TASK [dnsmasq : Check network file status] *************************************
2025-09-30 08:45:42.116788 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.041)       0:00:56.391 *****
2025-09-30 08:45:42.291369 | controller | ok: [instance]
2025-09-30 08:45:42.291455 | controller |
2025-09-30 08:45:42.291581 | controller | TASK [dnsmasq : Assert network exists] *****************************************
2025-09-30 08:45:42.291688 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.174)       0:00:56.566 *****
2025-09-30 08:45:42.312782 | controller | ok: [instance]
2025-09-30 08:45:42.312878 | controller |
2025-09-30 08:45:42.312976 | controller | TASK [dnsmasq : Initialize empty dhcp_host_entries] ****************************
2025-09-30 08:45:42.313079 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.021)       0:00:56.587 *****
2025-09-30 08:45:42.330303 | controller | ok: [instance]
2025-09-30 08:45:42.330477 | controller |
2025-09-30 08:45:42.330829 | controller | TASK [dnsmasq : Compute entry] *************************************************
2025-09-30 08:45:42.330937 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.017)       0:00:56.605 *****
2025-09-30 08:45:42.427748 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:eb:ec:27', 'ips': ['192.168.100.10', '']})
2025-09-30 08:45:42.427847 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:f4:0e:14', 'ips': ['192.168.100.11', '']})
2025-09-30 08:45:42.427954 | controller |
2025-09-30 08:45:42.428075 | controller | TASK [dnsmasq : Create add/remove sets] ****************************************
2025-09-30 08:45:42.428223 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.097)       0:00:56.702 *****
2025-09-30 08:45:42.465387 | controller | ok: [instance]
2025-09-30 08:45:42.465500 | controller |
2025-09-30 08:45:42.465638 | controller | TASK [dnsmasq : Add DHCP entries] **********************************************
2025-09-30 08:45:42.465745 | controller | Tuesday 30 September 2025  08:45:42 +0000 (0:00:00.037)       0:00:56.740 *****
2025-09-30 08:45:43.187820 | controller | changed: [instance] => (item={'file': 'public_compute-0_52:54:00:eb:ec:27', 'entry': '52:54:00:eb:ec:27,192.168.100.10,compute-0', 'state': 'present'})
2025-09-30 08:45:43.187901 | controller | changed: [instance] => (item={'file': 'public_compute-1_52:54:01:f4:0e:14', 'entry': '52:54:01:f4:0e:14,192.168.100.11,compute-1', 'state': 'present'})
2025-09-30 08:45:43.188006 | controller |
2025-09-30 08:45:43.188179 | controller | TASK [dnsmasq : Remove DHCP entries] *******************************************
2025-09-30 08:45:43.188233 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.722)       0:00:57.462 *****
2025-09-30 08:45:43.209830 | controller | skipping: [instance]
2025-09-30 08:45:43.209873 | controller |
2025-09-30 08:45:43.209990 | controller | TASK [libvirt_manager : Create per-network and .utility DNS entries] ***********
2025-09-30 08:45:43.210217 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.022)       0:00:57.484 *****
2025-09-30 08:45:43.336637 | controller | ok: [instance] => (item=compute-0)
2025-09-30 08:45:43.336700 | controller | ok: [instance] => (item=compute-1)
2025-09-30 08:45:43.336713 | controller |
2025-09-30 08:45:43.336826 | controller | TASK [Inject VMs in the .utility zone] *****************************************
2025-09-30 08:45:43.336919 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.126)       0:00:57.611 *****
2025-09-30 08:45:43.399673 | controller |
2025-09-30 08:45:43.399725 | controller | TASK [dnsmasq : Assert we have needed host record data] ************************
2025-09-30 08:45:43.399817 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.063)       0:00:57.674 *****
2025-09-30 08:45:43.441136 | controller | ok: [instance]
2025-09-30 08:45:43.441248 | controller |
2025-09-30 08:45:43.441370 | controller | TASK [dnsmasq : Assert each address element have needed data] ******************
2025-09-30 08:45:43.441482 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.040)       0:00:57.715 *****
2025-09-30 08:45:43.565478 | controller | ok: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-09-30 08:45:43.565536 | controller | ok: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-09-30 08:45:43.565626 | controller | ok: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2025-09-30 08:45:43.565745 | controller | ok: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-09-30 08:45:43.565854 | controller | ok: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-09-30 08:45:43.565958 | controller | ok: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2025-09-30 08:45:43.566044 | controller |
2025-09-30 08:45:43.566176 | controller | TASK [dnsmasq : Add/Remove address] ********************************************
2025-09-30 08:45:43.566270 | controller | Tuesday 30 September 2025  08:45:43 +0000 (0:00:00.123)       0:00:57.839 *****
2025-09-30 08:45:44.929457 | controller | changed: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-09-30 08:45:44.929535 | controller | changed: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-09-30 08:45:44.929651 | controller | changed: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2025-09-30 08:45:44.929771 | controller | changed: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-09-30 08:45:44.929880 | controller | changed: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-09-30 08:45:44.930004 | controller | changed: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2025-09-30 08:45:44.930138 | controller |
2025-09-30 08:45:44.930234 | controller | TASK [libvirt_manager : Ensure some domains are local] *************************
2025-09-30 08:45:44.930332 | controller | Tuesday 30 September 2025  08:45:44 +0000 (0:00:01.364)       0:00:59.203 *****
2025-09-30 08:45:45.311803 | controller | changed: [instance]
2025-09-30 08:45:45.311859 | controller |
2025-09-30 08:45:45.312029 | controller | TASK [libvirt_manager : Ensure dnsmasq is reloaded now] ************************
2025-09-30 08:45:45.312146 | controller | Tuesday 30 September 2025  08:45:45 +0000 (0:00:00.371)       0:00:59.575 *****
2025-09-30 08:45:45.312275 | controller |
2025-09-30 08:45:45.312404 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-09-30 08:45:45.312527 | controller | Tuesday 30 September 2025  08:45:45 +0000 (0:00:00.010)       0:00:59.586 *****
2025-09-30 08:45:46.159162 | controller | changed: [instance]
2025-09-30 08:45:46.159224 | controller |
2025-09-30 08:45:46.159354 | controller | RUNNING HANDLER [dnsmasq : Restart dnsmasq] ************************************
2025-09-30 08:45:46.159523 | controller | Tuesday 30 September 2025  08:45:46 +0000 (0:00:00.847)       0:01:00.433 *****
2025-09-30 08:45:46.517718 | controller | changed: [instance]
2025-09-30 08:45:46.517798 | controller |
2025-09-30 08:45:46.517812 | controller | RUNNING HANDLER [dnsmasq : Reload dnsmasq] *************************************
2025-09-30 08:45:46.517906 | controller | Tuesday 30 September 2025  08:45:46 +0000 (0:00:00.358)       0:01:00.792 *****
2025-09-30 08:45:46.875065 | controller | changed: [instance]
2025-09-30 08:45:46.875752 | controller |
2025-09-30 08:45:46.875824 | controller | TASK [libvirt_manager : Create group inventories] ******************************
2025-09-30 08:45:47.285171 | controller | Tuesday 30 September 2025  08:45:46 +0000 (0:00:00.357)       0:01:01.149 *****
2025-09-30 08:45:47.285242 | controller | changed: [instance] => (item=compute)
2025-09-30 08:45:47.285566 | controller |
2025-09-30 08:45:47.285591 | controller | TASK [libvirt_manager : Create "all" group inventory file] *********************
2025-09-30 08:45:47.700158 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.410)       0:01:01.559 *****
2025-09-30 08:45:47.700222 | controller | changed: [instance]
2025-09-30 08:45:47.700319 | controller |
2025-09-30 08:45:47.700331 | controller | TASK [libvirt_manager : Ensure storage pool is present.] ***********************
2025-09-30 08:45:47.700438 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.414)       0:01:01.974 *****
2025-09-30 08:45:47.737661 | controller | skipping: [instance]
2025-09-30 08:45:47.737741 | controller |
2025-09-30 08:45:47.737838 | controller | TASK [libvirt_manager : Ensure images are present] *****************************
2025-09-30 08:45:47.737960 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.037)       0:01:02.012 *****
2025-09-30 08:45:47.817141 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/get_image.yml for instance => (item=compute)
2025-09-30 08:45:47.817219 | controller |
2025-09-30 08:45:47.817292 | controller | TASK [libvirt_manager : Ensure directory exists] *******************************
2025-09-30 08:45:47.817418 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.079)       0:01:02.091 *****
2025-09-30 08:45:47.835226 | controller | skipping: [instance]
2025-09-30 08:45:47.835321 | controller |
2025-09-30 08:45:47.835449 | controller | TASK [libvirt_manager : Check if base image exists] ****************************
2025-09-30 08:45:47.835561 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.018)       0:01:02.110 *****
2025-09-30 08:45:47.856828 | controller | skipping: [instance]
2025-09-30 08:45:47.856903 | controller |
2025-09-30 08:45:47.857021 | controller | TASK [libvirt_manager : Download base image] ***********************************
2025-09-30 08:45:47.857171 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.021)       0:01:02.131 *****
2025-09-30 08:45:47.875723 | controller | skipping: [instance]
2025-09-30 08:45:47.875885 | controller |
2025-09-30 08:45:47.875976 | controller | TASK [libvirt_manager : Check image] *******************************************
2025-09-30 08:45:47.876121 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.018)       0:01:02.150 *****
2025-09-30 08:45:47.893244 | controller | skipping: [instance]
2025-09-30 08:45:47.893333 | controller |
2025-09-30 08:45:47.894005 | controller | TASK [libvirt_manager : Assert image status] ***********************************
2025-09-30 08:45:47.911828 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.017)       0:01:02.168 *****
2025-09-30 08:45:47.911872 | controller | skipping: [instance]
2025-09-30 08:45:47.911895 | controller |
2025-09-30 08:45:47.911977 | controller | TASK [libvirt_manager : Ensure image access rights] ****************************
2025-09-30 08:45:47.912072 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.018)       0:01:02.186 *****
2025-09-30 08:45:47.929039 | controller | skipping: [instance]
2025-09-30 08:45:47.929140 | controller |
2025-09-30 08:45:47.929272 | controller | TASK [libvirt_manager : Get ssh key state] *************************************
2025-09-30 08:45:47.929382 | controller | Tuesday 30 September 2025  08:45:47 +0000 (0:00:00.017)       0:01:02.204 *****
2025-09-30 08:45:48.104517 | controller | ok: [instance]
2025-09-30 08:45:48.104587 | controller |
2025-09-30 08:45:48.104702 | controller | TASK [libvirt_manager : Create temporary ssh keypair] **************************
2025-09-30 08:45:48.104799 | controller | Tuesday 30 September 2025  08:45:48 +0000 (0:00:00.175)       0:01:02.379 *****
2025-09-30 08:45:48.512259 | controller | changed: [instance]
2025-09-30 08:45:48.512310 | controller |
2025-09-30 08:45:48.512448 | controller | TASK [libvirt_manager : Slurp public key for later use] ************************
2025-09-30 08:45:48.512562 | controller | Tuesday 30 September 2025  08:45:48 +0000 (0:00:00.407)       0:01:02.786 *****
2025-09-30 08:45:48.798641 | controller | ok: [instance]
2025-09-30 08:45:48.798693 | controller |
2025-09-30 08:45:48.798818 | controller | TASK [libvirt_manager : Slurp private key for later use] ***********************
2025-09-30 08:45:48.798923 | controller | Tuesday 30 September 2025  08:45:48 +0000 (0:00:00.286)       0:01:03.073 *****
2025-09-30 08:45:48.977405 | controller | ok: [instance]
2025-09-30 08:45:48.977468 | controller |
2025-09-30 08:45:48.977601 | controller | TASK [libvirt_manager : Inject cifmw_reproducer_key.pub in hypervisor authorized_keys] ***
2025-09-30 08:45:48.977703 | controller | Tuesday 30 September 2025  08:45:48 +0000 (0:00:00.178)       0:01:03.251 *****
2025-09-30 08:45:49.371453 | controller | changed: [instance]
2025-09-30 08:45:49.371509 | controller |
2025-09-30 08:45:49.371634 | controller | TASK [libvirt_manager : Create fact holding network data for VMs] **************
2025-09-30 08:45:49.371743 | controller | Tuesday 30 September 2025  08:45:49 +0000 (0:00:00.394)       0:01:03.646 *****
2025-09-30 08:45:49.390556 | controller | ok: [instance]
2025-09-30 08:45:49.390663 | controller |
2025-09-30 08:45:49.390791 | controller | TASK [libvirt_manager : List existing networks] ********************************
2025-09-30 08:45:49.390922 | controller | Tuesday 30 September 2025  08:45:49 +0000 (0:00:00.019)       0:01:03.665 *****
2025-09-30 08:45:49.629488 | controller | ok: [instance]
2025-09-30 08:45:49.630200 | controller |
2025-09-30 08:45:49.976183 | controller | TASK [libvirt_manager : Gather pool fact] **************************************
2025-09-30 08:45:49.976216 | controller | Tuesday 30 September 2025  08:45:49 +0000 (0:00:00.238)       0:01:03.904 *****
2025-09-30 08:45:49.976230 | controller | ok: [instance]
2025-09-30 08:45:49.976363 | controller |
2025-09-30 08:45:49.976374 | controller | TASK [libvirt_manager : Create and run VMs] ************************************
2025-09-30 08:45:49.976473 | controller | Tuesday 30 September 2025  08:45:49 +0000 (0:00:00.346)       0:01:04.250 *****
2025-09-30 08:45:50.055907 | 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'})
2025-09-30 08:45:50.056027 | 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'})
2025-09-30 08:45:50.056162 | controller |
2025-09-30 08:45:50.056292 | controller | TASK [libvirt_manager : Create VM image for compute-0] *************************
2025-09-30 08:45:50.056435 | controller | Tuesday 30 September 2025  08:45:50 +0000 (0:00:00.079)       0:01:04.330 *****
2025-09-30 08:45:50.315670 | controller | changed: [instance]
2025-09-30 08:45:50.315738 | controller |
2025-09-30 08:45:50.315856 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-0] ********
2025-09-30 08:45:50.315955 | controller | Tuesday 30 September 2025  08:45:50 +0000 (0:00:00.259)       0:01:04.590 *****
2025-09-30 08:45:50.545277 | controller | changed: [instance]
2025-09-30 08:45:50.545413 | controller |
2025-09-30 08:45:50.545611 | controller | TASK [libvirt_manager : Define VMs for type compute-0] *************************
2025-09-30 08:45:50.947906 | controller | Tuesday 30 September 2025  08:45:50 +0000 (0:00:00.229)       0:01:04.819 *****
2025-09-30 08:45:50.947947 | controller | changed: [instance]
2025-09-30 08:45:50.947979 | controller |
2025-09-30 08:45:50.948273 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-0] ***********
2025-09-30 08:45:50.973825 | controller | Tuesday 30 September 2025  08:45:50 +0000 (0:00:00.402)       0:01:05.222 *****
2025-09-30 08:45:50.973863 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2025-09-30 08:45:51.007556 | controller |
2025-09-30 08:45:51.007581 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2025-09-30 08:45:51.007589 | controller | Tuesday 30 September 2025  08:45:50 +0000 (0:00:00.025)       0:01:05.248 *****
2025-09-30 08:45:51.007599 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2025-09-30 08:45:51.247609 | controller |
2025-09-30 08:45:51.247641 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2025-09-30 08:45:51.247649 | controller | Tuesday 30 September 2025  08:45:51 +0000 (0:00:00.033)       0:01:05.282 *****
2025-09-30 08:45:51.247659 | controller | ok: [instance]
2025-09-30 08:45:51.247685 | controller |
2025-09-30 08:45:51.247695 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2025-09-30 08:45:51.247826 | controller | Tuesday 30 September 2025  08:45:51 +0000 (0:00:00.240)       0:01:05.522 *****
2025-09-30 08:45:51.295650 | controller | ok: [instance] => (item=crc)
2025-09-30 08:45:51.295795 | controller | ok: [instance] => (item=default)
2025-09-30 08:45:51.295810 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:51.295922 | controller |
2025-09-30 08:45:51.295937 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2025-09-30 08:45:51.296034 | controller | Tuesday 30 September 2025  08:45:51 +0000 (0:00:00.047)       0:01:05.570 *****
2025-09-30 08:45:51.531536 | controller | ok: [instance]
2025-09-30 08:45:51.531588 | controller |
2025-09-30 08:45:51.531703 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2025-09-30 08:45:51.531805 | controller | Tuesday 30 September 2025  08:45:51 +0000 (0:00:00.235)       0:01:05.806 *****
2025-09-30 08:45:51.736398 | controller | ok: [instance]
2025-09-30 08:45:51.736453 | controller |
2025-09-30 08:45:51.736588 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-0] ************
2025-09-30 08:45:51.736692 | controller | Tuesday 30 September 2025  08:45:51 +0000 (0:00:00.201)       0:01:06.007 *****
2025-09-30 08:45:52.038179 | controller | changed: [instance]
2025-09-30 08:45:52.038282 | controller |
2025-09-30 08:45:52.038439 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-0] *****
2025-09-30 08:45:52.038543 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.305)       0:01:06.312 *****
2025-09-30 08:45:52.057712 | controller | skipping: [instance]
2025-09-30 08:45:52.057822 | controller |
2025-09-30 08:45:52.057957 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-0] ********
2025-09-30 08:45:52.058057 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.019)       0:01:06.332 *****
2025-09-30 08:45:52.084497 | controller | skipping: [instance]
2025-09-30 08:45:52.084607 | controller |
2025-09-30 08:45:52.084727 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-0] **************
2025-09-30 08:45:52.084848 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.026)       0:01:06.359 *****
2025-09-30 08:45:52.110633 | controller | skipping: [instance]
2025-09-30 08:45:52.110718 | controller |
2025-09-30 08:45:52.110831 | controller | TASK [libvirt_manager : Attach volumes for VM compute-0] ***********************
2025-09-30 08:45:52.110933 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.026)       0:01:06.385 *****
2025-09-30 08:45:52.135818 | controller | skipping: [instance]
2025-09-30 08:45:52.135921 | controller |
2025-09-30 08:45:52.136064 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2025-09-30 08:45:52.136221 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.025)       0:01:06.410 *****
2025-09-30 08:45:52.359574 | controller | changed: [instance]
2025-09-30 08:45:52.359705 | controller |
2025-09-30 08:45:52.359817 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2025-09-30 08:45:52.359918 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.223)       0:01:06.634 *****
2025-09-30 08:45:52.394462 | controller | ok: [instance]
2025-09-30 08:45:52.394551 | controller |
2025-09-30 08:45:52.394651 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2025-09-30 08:45:52.394747 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.035)       0:01:06.669 *****
2025-09-30 08:45:52.413955 | controller | skipping: [instance]
2025-09-30 08:45:52.414039 | controller |
2025-09-30 08:45:52.414161 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2025-09-30 08:45:52.414260 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.019)       0:01:06.689 *****
2025-09-30 08:45:52.433550 | controller | skipping: [instance]
2025-09-30 08:45:52.433650 | controller |
2025-09-30 08:45:52.433775 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2025-09-30 08:45:52.433893 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.019)       0:01:06.708 *****
2025-09-30 08:45:52.478642 | controller | skipping: [instance]
2025-09-30 08:45:52.478758 | controller |
2025-09-30 08:45:52.478898 | controller | TASK [libvirt_manager : Create VM image for compute-1] *************************
2025-09-30 08:45:52.479026 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.045)       0:01:06.753 *****
2025-09-30 08:45:52.738075 | controller | changed: [instance]
2025-09-30 08:45:52.738145 | controller |
2025-09-30 08:45:52.738254 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-1] ********
2025-09-30 08:45:52.738363 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.259)       0:01:07.012 *****
2025-09-30 08:45:52.968665 | controller | changed: [instance]
2025-09-30 08:45:52.968840 | controller |
2025-09-30 08:45:52.968950 | controller | TASK [libvirt_manager : Define VMs for type compute-1] *************************
2025-09-30 08:45:52.969058 | controller | Tuesday 30 September 2025  08:45:52 +0000 (0:00:00.229)       0:01:07.242 *****
2025-09-30 08:45:53.285435 | controller | changed: [instance]
2025-09-30 08:45:53.285502 | controller |
2025-09-30 08:45:53.285600 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-1] ***********
2025-09-30 08:45:53.285703 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.317)       0:01:07.560 *****
2025-09-30 08:45:53.311886 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2025-09-30 08:45:53.311961 | controller |
2025-09-30 08:45:53.312064 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2025-09-30 08:45:53.312193 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.026)       0:01:07.586 *****
2025-09-30 08:45:53.343899 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2025-09-30 08:45:53.344003 | controller |
2025-09-30 08:45:53.344150 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2025-09-30 08:45:53.344275 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.032)       0:01:07.618 *****
2025-09-30 08:45:53.590807 | controller | ok: [instance]
2025-09-30 08:45:53.590894 | controller |
2025-09-30 08:45:53.591013 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2025-09-30 08:45:53.591143 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.246)       0:01:07.865 *****
2025-09-30 08:45:53.640594 | controller | ok: [instance] => (item=crc)
2025-09-30 08:45:53.640645 | controller | ok: [instance] => (item=default)
2025-09-30 08:45:53.640743 | controller | ok: [instance] => (item=cifmw-public)
2025-09-30 08:45:53.640822 | controller |
2025-09-30 08:45:53.640925 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2025-09-30 08:45:53.641024 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.049)       0:01:07.915 *****
2025-09-30 08:45:53.885419 | controller | ok: [instance]
2025-09-30 08:45:53.885503 | controller |
2025-09-30 08:45:53.885618 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2025-09-30 08:45:53.885717 | controller | Tuesday 30 September 2025  08:45:53 +0000 (0:00:00.244)       0:01:08.160 *****
2025-09-30 08:45:54.091684 | controller | ok: [instance]
2025-09-30 08:45:54.091746 | controller |
2025-09-30 08:45:54.091820 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-1] ************
2025-09-30 08:45:54.091923 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.206)       0:01:08.366 *****
2025-09-30 08:45:54.391061 | controller | changed: [instance]
2025-09-30 08:45:54.391141 | controller |
2025-09-30 08:45:54.391237 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-1] *****
2025-09-30 08:45:54.391331 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.299)       0:01:08.665 *****
2025-09-30 08:45:54.410702 | controller | skipping: [instance]
2025-09-30 08:45:54.410796 | controller |
2025-09-30 08:45:54.410906 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-1] ********
2025-09-30 08:45:54.411005 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.019)       0:01:08.685 *****
2025-09-30 08:45:54.436012 | controller | skipping: [instance]
2025-09-30 08:45:54.436091 | controller |
2025-09-30 08:45:54.436237 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-1] **************
2025-09-30 08:45:54.436366 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.025)       0:01:08.711 *****
2025-09-30 08:45:54.469792 | controller | skipping: [instance]
2025-09-30 08:45:54.469861 | controller |
2025-09-30 08:45:54.469954 | controller | TASK [libvirt_manager : Attach volumes for VM compute-1] ***********************
2025-09-30 08:45:54.470060 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.032)       0:01:08.743 *****
2025-09-30 08:45:54.495203 | controller | skipping: [instance]
2025-09-30 08:45:54.497081 | controller |
2025-09-30 08:45:54.731236 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2025-09-30 08:45:54.731280 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.026)       0:01:08.769 *****
2025-09-30 08:45:54.731293 | controller | changed: [instance]
2025-09-30 08:45:54.731313 | controller |
2025-09-30 08:45:54.731409 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2025-09-30 08:45:54.731511 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.236)       0:01:09.005 *****
2025-09-30 08:45:54.766295 | controller | ok: [instance]
2025-09-30 08:45:54.766403 | controller |
2025-09-30 08:45:54.766536 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2025-09-30 08:45:54.766635 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.035)       0:01:09.041 *****
2025-09-30 08:45:54.786895 | controller | skipping: [instance]
2025-09-30 08:45:54.786974 | controller |
2025-09-30 08:45:54.787076 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2025-09-30 08:45:54.787199 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.020)       0:01:09.061 *****
2025-09-30 08:45:54.806543 | controller | skipping: [instance]
2025-09-30 08:45:54.806632 | controller |
2025-09-30 08:45:54.806746 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2025-09-30 08:45:54.806832 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.019)       0:01:09.081 *****
2025-09-30 08:45:54.848487 | controller | skipping: [instance]
2025-09-30 08:45:54.848581 | controller |
2025-09-30 08:45:54.848713 | controller | TASK [libvirt_manager : Start (power-on) VMs] **********************************
2025-09-30 08:45:54.848803 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.041)       0:01:09.123 *****
2025-09-30 08:45:54.886675 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/start_vms.yml for instance
2025-09-30 08:45:54.886795 | controller |
2025-09-30 08:45:54.886897 | controller | TASK [libvirt_manager : Refresh oooq_pool before starting VMs] *****************
2025-09-30 08:45:54.886994 | controller | Tuesday 30 September 2025  08:45:54 +0000 (0:00:00.038)       0:01:09.161 *****
2025-09-30 08:45:55.136748 | controller | ok: [instance] => (item=crc)
2025-09-30 08:45:55.136816 | controller |
2025-09-30 08:45:55.136920 | controller | TASK [libvirt_manager : Start VMs for type {{ vm_type }}] **********************
2025-09-30 08:45:55.137029 | controller | Tuesday 30 September 2025  08:45:55 +0000 (0:00:00.249)       0:01:09.411 *****
2025-09-30 08:45:56.184223 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-09-30 08:45:56.184279 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-09-30 08:45:56.184414 | controller | skipping: [instance]
2025-09-30 08:45:56.184511 | controller |
2025-09-30 08:45:56.184629 | controller | TASK [libvirt_manager : Wait for SSH on started VMs] ***************************
2025-09-30 08:45:56.184733 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:01.047)       0:01:10.458 *****
2025-09-30 08:45:56.235993 | controller | skipping: [instance] => (item=compute-0.utility)
2025-09-30 08:45:56.236271 | controller | skipping: [instance] => (item=compute-1.utility)
2025-09-30 08:45:56.236306 | controller | skipping: [instance]
2025-09-30 08:45:56.236393 | controller |
2025-09-30 08:45:56.236404 | controller | TASK [libvirt_manager : Ensure we get SSH on nodes] ****************************
2025-09-30 08:45:56.236615 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.051)       0:01:10.510 *****
2025-09-30 08:45:56.265623 | 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'})
2025-09-30 08:45:56.265674 | 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'})
2025-09-30 08:45:56.265786 | controller | skipping: [instance]
2025-09-30 08:45:56.265865 | controller |
2025-09-30 08:45:56.265960 | controller | TASK [libvirt_manager : Configure managed VMs] *********************************
2025-09-30 08:45:56.266066 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.029)       0:01:10.540 *****
2025-09-30 08:45:56.308580 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-09-30 08:45:56.308682 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-09-30 08:45:56.308816 | controller | skipping: [instance]
2025-09-30 08:45:56.308921 | controller |
2025-09-30 08:45:56.309041 | controller | TASK [Create VBMC entity] ******************************************************
2025-09-30 08:45:56.309183 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.042)       0:01:10.583 *****
2025-09-30 08:45:56.347650 | controller | skipping: [instance] => (item=compute-0)
2025-09-30 08:45:56.347701 | controller | skipping: [instance] => (item=compute-1)
2025-09-30 08:45:56.347813 | controller | skipping: [instance]
2025-09-30 08:45:56.347890 | controller |
2025-09-30 08:45:56.347985 | controller | TASK [libvirt_manager : List running virtual machines.] ************************
2025-09-30 08:45:56.348078 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.039)       0:01:10.622 *****
2025-09-30 08:45:56.571948 | controller | ok: [instance]
2025-09-30 08:45:56.572079 | controller |
2025-09-30 08:45:56.572245 | controller | TASK [libvirt_manager : Dump UUIDs] ********************************************
2025-09-30 08:45:56.572404 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.224)       0:01:10.846 *****
2025-09-30 08:45:56.951890 | controller | changed: [instance]
2025-09-30 08:45:56.951942 | controller |
2025-09-30 08:45:56.952045 | controller | TASK [Ensure fresh vbmc listing] ***********************************************
2025-09-30 08:45:56.952158 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.378)       0:01:11.225 *****
2025-09-30 08:45:56.989521 | controller | skipping: [instance]
2025-09-30 08:45:56.989624 | controller |
2025-09-30 08:45:56.989761 | controller | TASK [libvirt_manager : Update vbmc related fact] ******************************
2025-09-30 08:45:56.989869 | controller | Tuesday 30 September 2025  08:45:56 +0000 (0:00:00.038)       0:01:11.264 *****
2025-09-30 08:45:57.021954 | controller | skipping: [instance]
2025-09-30 08:45:57.022047 | controller |
2025-09-30 08:45:57.022199 | controller | TASK [libvirt_manager : Dump vbmc known hosts] *********************************
2025-09-30 08:45:57.022329 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.032)       0:01:11.296 *****
2025-09-30 08:45:57.052888 | controller | skipping: [instance]
2025-09-30 08:45:57.052988 | controller |
2025-09-30 08:45:57.053090 | controller | TASK [libvirt_manager : Copy authorized_keys] **********************************
2025-09-30 08:45:57.053216 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.030)       0:01:11.327 *****
2025-09-30 08:45:57.076458 | controller | skipping: [instance]
2025-09-30 08:45:57.076534 | controller |
2025-09-30 08:45:57.076639 | controller | TASK [libvirt_manager : Enable root access on CRC] *****************************
2025-09-30 08:45:57.076804 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.023)       0:01:11.351 *****
2025-09-30 08:45:57.105477 | controller | skipping: [instance]
2025-09-30 08:45:57.105513 | controller |
2025-09-30 08:45:57.105661 | controller | TASK [Generate baremetal-info fact] ********************************************
2025-09-30 08:45:57.105714 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.028)       0:01:11.380 *****
2025-09-30 08:45:57.176735 | controller |
2025-09-30 08:45:57.176792 | controller | TASK [reproducer : Ensure directories exist] ***********************************
2025-09-30 08:45:57.176885 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.071)       0:01:11.451 *****
2025-09-30 08:45:57.557646 | controller | changed: [instance] => (item=parameters)
2025-09-30 08:45:57.557726 | controller | ok: [instance] => (item=artifacts)
2025-09-30 08:45:57.557830 | controller |
2025-09-30 08:45:57.557937 | controller | TASK [reproducer : Convert VBMC list into a dict for better usage] *************
2025-09-30 08:45:57.558039 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.380)       0:01:11.832 *****
2025-09-30 08:45:57.588578 | controller | skipping: [instance]
2025-09-30 08:45:57.588630 | controller |
2025-09-30 08:45:57.588769 | controller | TASK [reproducer : Check if baremetal-info.yml exists] *************************
2025-09-30 08:45:57.588904 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.031)       0:01:11.863 *****
2025-09-30 08:45:57.775300 | controller | ok: [instance]
2025-09-30 08:45:57.775370 | controller |
2025-09-30 08:45:57.775481 | controller | TASK [reproducer : Get content of baremetal-info file] *************************
2025-09-30 08:45:57.775599 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.186)       0:01:12.050 *****
2025-09-30 08:45:57.792189 | controller | skipping: [instance]
2025-09-30 08:45:57.792269 | controller |
2025-09-30 08:45:57.792401 | controller | TASK [reproducer : Interpret remote file content as yaml] **********************
2025-09-30 08:45:57.792499 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.017)       0:01:12.067 *****
2025-09-30 08:45:57.819873 | controller | skipping: [instance]
2025-09-30 08:45:57.819956 | controller |
2025-09-30 08:45:57.820072 | controller | TASK [reproducer : Slurp content of: /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2025-09-30 08:45:57.820189 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.027)       0:01:12.094 *****
2025-09-30 08:45:57.843906 | controller | skipping: [instance]
2025-09-30 08:45:57.844002 | controller |
2025-09-30 08:45:57.844170 | controller | TASK [reproducer : Set cifmw_libvirt_manager_mac_map fact from /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2025-09-30 08:45:57.844294 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.023)       0:01:12.118 *****
2025-09-30 08:45:57.865603 | controller | skipping: [instance]
2025-09-30 08:45:57.865681 | controller |
2025-09-30 08:45:57.865787 | controller | TASK [reproducer : Generate libvirt_manager_bm_info_data fact] *****************
2025-09-30 08:45:57.865885 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.021)       0:01:12.140 *****
2025-09-30 08:45:57.936873 | controller | ok: [instance] => (item={'key': 'cifmw-compute-0', 'value': '52b54bc3-3135-4a8b-8fc0-c325d6dc4300'})
2025-09-30 08:45:57.936978 | controller | ok: [instance] => (item={'key': 'cifmw-compute-1', 'value': 'ff5726cc-6eef-462c-a5c1-225c9ac6f424'})
2025-09-30 08:45:57.937092 | controller |
2025-09-30 08:45:57.937241 | controller | TASK [reproducer : Output baremetal info file] *********************************
2025-09-30 08:45:57.937355 | controller | Tuesday 30 September 2025  08:45:57 +0000 (0:00:00.070)       0:01:12.211 *****
2025-09-30 08:45:58.275407 | controller | changed: [instance]
2025-09-30 08:45:58.275458 | controller |
2025-09-30 08:45:58.275583 | controller | TASK [reproducer : Output ironic_nodes to file] ********************************
2025-09-30 08:45:58.275693 | controller | Tuesday 30 September 2025  08:45:58 +0000 (0:00:00.338)       0:01:12.550 *****
2025-09-30 08:45:58.297805 | controller | skipping: [instance]
2025-09-30 08:45:58.297891 | controller |
2025-09-30 08:45:58.297988 | controller | TASK [Run Sushy Emulator role against OCP] *************************************
2025-09-30 08:45:58.298087 | controller | Tuesday 30 September 2025  08:45:58 +0000 (0:00:00.022)       0:01:12.572 *****
2025-09-30 08:45:58.358904 | controller |
2025-09-30 08:45:58.358979 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] ***************
2025-09-30 08:45:58.359088 | controller | Tuesday 30 September 2025  08:45:58 +0000 (0:00:00.061)       0:01:12.633 *****
2025-09-30 08:45:58.566299 | controller | changed: [instance]
2025-09-30 08:45:58.566376 | controller |
2025-09-30 08:45:58.566495 | controller | TASK [sushy_emulator : Install required packages] ******************************
2025-09-30 08:45:58.566601 | controller | Tuesday 30 September 2025  08:45:58 +0000 (0:00:00.207)       0:01:12.840 *****
2025-09-30 08:46:01.053375 | controller | changed: [instance]
2025-09-30 08:46:01.053712 | controller |
2025-09-30 08:46:01.648790 | controller | TASK [sushy_emulator : Get ingresses domain] ***********************************
2025-09-30 08:46:01.648839 | controller | Tuesday 30 September 2025  08:46:01 +0000 (0:00:02.487)       0:01:15.328 *****
2025-09-30 08:46:01.648852 | controller | changed: [instance]
2025-09-30 08:46:01.648871 | controller |
2025-09-30 08:46:01.648879 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] *********************
2025-09-30 08:46:01.648987 | controller | Tuesday 30 September 2025  08:46:01 +0000 (0:00:00.595)       0:01:15.923 *****
2025-09-30 08:46:01.670626 | controller | ok: [instance]
2025-09-30 08:46:01.670754 | controller |
2025-09-30 08:46:01.670769 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] **********************
2025-09-30 08:46:01.919648 | controller | Tuesday 30 September 2025  08:46:01 +0000 (0:00:00.022)       0:01:15.945 *****
2025-09-30 08:46:01.919683 | controller | changed: [instance]
2025-09-30 08:46:02.099746 | controller |
2025-09-30 08:46:02.099778 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ********************
2025-09-30 08:46:02.099787 | controller | Tuesday 30 September 2025  08:46:01 +0000 (0:00:00.248)       0:01:16.194 *****
2025-09-30 08:46:02.099797 | controller | ok: [instance]
2025-09-30 08:46:03.235709 | controller |
2025-09-30 08:46:03.235739 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] *******************************
2025-09-30 08:46:03.235747 | controller | Tuesday 30 September 2025  08:46:02 +0000 (0:00:00.180)       0:01:16.374 *****
2025-09-30 08:46:03.235758 | controller | changed: [instance -> controller-0(192.168.26.58)]
2025-09-30 08:46:03.476749 | controller |
2025-09-30 08:46:03.476779 | controller | TASK [sushy_emulator : Run ssh-keyscan] ****************************************
2025-09-30 08:46:03.476787 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:01.135)       0:01:17.510 *****
2025-09-30 08:46:03.476803 | controller | changed: [instance]
2025-09-30 08:46:03.825710 | controller |
2025-09-30 08:46:03.825752 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************
2025-09-30 08:46:03.825760 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.241)       0:01:17.751 *****
2025-09-30 08:46:03.825770 | controller | changed: [instance]
2025-09-30 08:46:03.825790 | controller |
2025-09-30 08:46:03.825890 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:46:03.825991 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.349)       0:01:18.100 *****
2025-09-30 08:46:03.853027 | controller | skipping: [instance]
2025-09-30 08:46:03.853132 | controller |
2025-09-30 08:46:03.853244 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:46:03.853355 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.027)       0:01:18.127 *****
2025-09-30 08:46:03.881032 | controller | skipping: [instance]
2025-09-30 08:46:03.881087 | controller |
2025-09-30 08:46:03.881254 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:46:03.881360 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.028)       0:01:18.155 *****
2025-09-30 08:46:03.904777 | controller | skipping: [instance]
2025-09-30 08:46:03.904873 | controller |
2025-09-30 08:46:03.904977 | controller | TASK [sushy_emulator : Generate list of filtered VMs] **************************
2025-09-30 08:46:03.905076 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.023)       0:01:18.179 *****
2025-09-30 08:46:03.941289 | controller | ok: [instance]
2025-09-30 08:46:03.941353 | controller |
2025-09-30 08:46:03.941491 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] ***************************
2025-09-30 08:46:03.941608 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.036)       0:01:18.216 *****
2025-09-30 08:46:03.961239 | controller | skipping: [instance]
2025-09-30 08:46:03.961349 | controller |
2025-09-30 08:46:03.961455 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ********
2025-09-30 08:46:03.961554 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.019)       0:01:18.236 *****
2025-09-30 08:46:03.980390 | controller | skipping: [instance]
2025-09-30 08:46:03.980478 | controller |
2025-09-30 08:46:03.980581 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] ***************
2025-09-30 08:46:03.980692 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.019)       0:01:18.255 *****
2025-09-30 08:46:03.998673 | controller | skipping: [instance]
2025-09-30 08:46:03.998769 | controller |
2025-09-30 08:46:03.998895 | controller | TASK [sushy_emulator : Generate htpasswd string] *******************************
2025-09-30 08:46:03.999016 | controller | Tuesday 30 September 2025  08:46:03 +0000 (0:00:00.018)       0:01:18.273 *****
2025-09-30 08:46:04.188770 | controller | changed: [instance]
2025-09-30 08:46:04.188826 | controller |
2025-09-30 08:46:04.188924 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] *********************
2025-09-30 08:46:04.189028 | controller | Tuesday 30 September 2025  08:46:04 +0000 (0:00:00.189)       0:01:18.463 *****
2025-09-30 08:46:05.971766 | controller | changed: [instance] => (item=secret)
2025-09-30 08:46:05.971847 | controller | changed: [instance] => (item=configmap)
2025-09-30 08:46:05.971960 | controller | changed: [instance] => (item=pod)
2025-09-30 08:46:05.972124 | controller | changed: [instance] => (item=service)
2025-09-30 08:46:05.972292 | controller | changed: [instance] => (item=route)
2025-09-30 08:46:05.972440 | controller |
2025-09-30 08:46:05.972589 | controller | TASK [sushy_emulator : Write sushy emulator config] ****************************
2025-09-30 08:46:05.972728 | controller | Tuesday 30 September 2025  08:46:05 +0000 (0:00:01.782)       0:01:20.246 *****
2025-09-30 08:46:05.994257 | controller | skipping: [instance]
2025-09-30 08:46:05.994293 | controller |
2025-09-30 08:46:05.994459 | controller | TASK [sushy_emulator : Write htpasswd string to file] **************************
2025-09-30 08:46:05.994611 | controller | Tuesday 30 September 2025  08:46:05 +0000 (0:00:00.022)       0:01:20.269 *****
2025-09-30 08:46:06.019869 | controller | skipping: [instance]
2025-09-30 08:46:06.020001 | controller |
2025-09-30 08:46:06.020145 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ********************
2025-09-30 08:46:06.020306 | controller | Tuesday 30 September 2025  08:46:06 +0000 (0:00:00.025)       0:01:20.294 *****
2025-09-30 08:46:07.012148 | controller | changed: [instance]
2025-09-30 08:46:07.012267 | controller |
2025-09-30 08:46:07.012444 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] ***
2025-09-30 08:46:07.012613 | controller | Tuesday 30 September 2025  08:46:07 +0000 (0:00:00.991)       0:01:21.286 *****
2025-09-30 08:47:48.964997 | controller | ok: [instance]
2025-09-30 08:47:52.520129 | controller |
2025-09-30 08:47:52.520164 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] *************************
2025-09-30 08:47:52.520172 | controller | Tuesday 30 September 2025  08:47:48 +0000 (0:01:41.951)       0:03:03.238 *****
2025-09-30 08:47:52.520187 | controller | changed: [instance] => (item=secret)
2025-09-30 08:48:53.299405 | controller | changed: [instance] => (item=configmap)
2025-09-30 08:48:53.299476 | controller | changed: [instance] => (item=service)
2025-09-30 08:48:53.299485 | controller | changed: [instance] => (item=route)
2025-09-30 08:48:53.299491 | controller |
2025-09-30 08:48:53.299497 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] **********************
2025-09-30 08:48:53.299503 | controller | Tuesday 30 September 2025  08:47:52 +0000 (0:00:03.556)       0:03:06.794 *****
2025-09-30 08:48:53.299515 | controller | [WARNING]: unknown field "spec.selector"
2025-09-30 08:48:53.299637 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299650 | controller | "spec.containers[0].readinessProbe.httpGet.initialDelaySeconds"
2025-09-30 08:48:53.299656 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299662 | controller | "spec.containers[0].readinessProbe.httpGet.periodSeconds"
2025-09-30 08:48:53.299670 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299801 | controller | "spec.containers[0].livenessProbe.httpGet.initialDelaySeconds"
2025-09-30 08:48:53.299816 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299822 | controller | "spec.containers[0].livenessProbe.httpGet.failureThreshold"
2025-09-30 08:48:53.299828 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299833 | controller | "spec.containers[0].livenessProbe.httpGet.periodSeconds"
2025-09-30 08:48:53.299839 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299846 | controller | "spec.containers[0].startupProbe.httpGet.failureThreshold"
2025-09-30 08:48:53.299931 | controller | [WARNING]: unknown field
2025-09-30 08:48:53.299964 | controller | "spec.containers[0].startupProbe.httpGet.initialDelaySeconds"
2025-09-30 08:48:53.306935 | controller | changed: [instance]
2025-09-30 08:48:53.306971 | controller |
2025-09-30 08:48:53.306981 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-09-30 08:48:53.307073 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:01:00.787)       0:04:07.581 *****
2025-09-30 08:48:53.329322 | controller | skipping: [instance]
2025-09-30 08:48:53.329417 | controller |
2025-09-30 08:48:53.329543 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-09-30 08:48:53.329664 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.018)       0:04:07.600 *****
2025-09-30 08:48:53.352254 | controller | skipping: [instance]
2025-09-30 08:48:53.352351 | controller |
2025-09-30 08:48:53.352474 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-09-30 08:48:53.352569 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.026)       0:04:07.627 *****
2025-09-30 08:48:53.375346 | controller | skipping: [instance]
2025-09-30 08:48:53.375438 | controller |
2025-09-30 08:48:53.375543 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-09-30 08:48:53.375633 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.023)       0:04:07.650 *****
2025-09-30 08:48:53.395240 | controller | skipping: [instance]
2025-09-30 08:48:53.395358 | controller |
2025-09-30 08:48:53.395491 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-09-30 08:48:53.395623 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.019)       0:04:07.670 *****
2025-09-30 08:48:53.419720 | controller | skipping: [instance]
2025-09-30 08:48:53.419827 | controller |
2025-09-30 08:48:53.419969 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ********************
2025-09-30 08:48:53.420096 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.024)       0:04:07.694 *****
2025-09-30 08:48:53.438868 | controller | skipping: [instance]
2025-09-30 08:48:53.438986 | controller |
2025-09-30 08:48:53.439127 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] **************
2025-09-30 08:48:53.439252 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.019)       0:04:07.713 *****
2025-09-30 08:48:53.462547 | controller | skipping: [instance]
2025-09-30 08:48:53.462633 | controller |
2025-09-30 08:48:53.462744 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] *******************
2025-09-30 08:48:53.462842 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.023)       0:04:07.737 *****
2025-09-30 08:48:53.531335 | controller |
2025-09-30 08:48:53.531454 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] ***
2025-09-30 08:48:53.531547 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.068)       0:04:07.806 *****
2025-09-30 08:48:53.562465 | controller | ok: [instance]
2025-09-30 08:48:53.562560 | controller |
2025-09-30 08:48:53.562663 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-09-30 08:48:53.562776 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.031)       0:04:07.837 *****
2025-09-30 08:48:53.589213 | controller | skipping: [instance]
2025-09-30 08:48:53.589309 | controller |
2025-09-30 08:48:53.589425 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-09-30 08:48:53.589507 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.026)       0:04:07.864 *****
2025-09-30 08:48:53.613574 | controller | skipping: [instance]
2025-09-30 08:48:53.613653 | controller |
2025-09-30 08:48:53.613760 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] ***
2025-09-30 08:48:53.613873 | controller | Tuesday 30 September 2025  08:48:53 +0000 (0:00:00.024)       0:04:07.888 *****
2025-09-30 08:48:54.738060 | controller | ok: [instance]
2025-09-30 08:48:57.230852 | controller |
2025-09-30 08:48:57.230889 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] ***
2025-09-30 08:48:57.230897 | controller | Tuesday 30 September 2025  08:48:54 +0000 (0:00:01.123)       0:04:09.012 *****
2025-09-30 08:48:57.230909 | controller | ok: [instance] => (item=52b54bc3-3135-4a8b-8fc0-c325d6dc4300)
2025-09-30 08:48:57.231500 | controller | ok: [instance] => (item=ff5726cc-6eef-462c-a5c1-225c9ac6f424)
2025-09-30 08:48:57.231516 | controller |
2025-09-30 08:48:57.231523 | controller | TASK [sushy_emulator : Verify baremetal VM power status] ***********************
2025-09-30 08:48:57.231532 | controller | Tuesday 30 September 2025  08:48:57 +0000 (0:00:02.492)       0:04:11.505 *****
2025-09-30 08:48:57.279505 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-09-30 08:48:57.279566 | controller | ok: [instance] => (item=cifmw-compute-1)
2025-09-30 08:48:57.279574 | controller |
2025-09-30 08:48:57.279583 | controller | TASK [Run Sushy Emulator role against podman] **********************************
2025-09-30 08:48:57.279693 | controller | Tuesday 30 September 2025  08:48:57 +0000 (0:00:00.048)       0:04:11.554 *****
2025-09-30 08:48:57.367499 | controller |
2025-09-30 08:48:57.625717 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] ***************
2025-09-30 08:48:57.625761 | controller | Tuesday 30 September 2025  08:48:57 +0000 (0:00:00.088)       0:04:11.642 *****
2025-09-30 08:48:57.625776 | controller | ok: [instance]
2025-09-30 08:48:57.625833 | controller |
2025-09-30 08:48:57.625845 | controller | TASK [sushy_emulator : Install required packages] ******************************
2025-09-30 08:48:57.625928 | controller | Tuesday 30 September 2025  08:48:57 +0000 (0:00:00.258)       0:04:11.900 *****
2025-09-30 08:48:58.911230 | controller | ok: [instance]
2025-09-30 08:48:58.911287 | controller |
2025-09-30 08:48:58.911297 | controller | TASK [sushy_emulator : Get ingresses domain] ***********************************
2025-09-30 08:48:58.911313 | controller | Tuesday 30 September 2025  08:48:58 +0000 (0:00:01.285)       0:04:13.185 *****
2025-09-30 08:48:58.930796 | controller | skipping: [instance]
2025-09-30 08:48:58.949182 | controller |
2025-09-30 08:48:58.949208 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] *********************
2025-09-30 08:48:58.949217 | controller | Tuesday 30 September 2025  08:48:58 +0000 (0:00:00.019)       0:04:13.205 *****
2025-09-30 08:48:58.949227 | controller | skipping: [instance]
2025-09-30 08:48:59.212330 | controller |
2025-09-30 08:48:59.212377 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] **********************
2025-09-30 08:48:59.212386 | controller | Tuesday 30 September 2025  08:48:58 +0000 (0:00:00.018)       0:04:13.223 *****
2025-09-30 08:48:59.212397 | controller | ok: [instance]
2025-09-30 08:48:59.212624 | controller |
2025-09-30 08:48:59.212639 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ********************
2025-09-30 08:48:59.390457 | controller | Tuesday 30 September 2025  08:48:59 +0000 (0:00:00.263)       0:04:13.487 *****
2025-09-30 08:48:59.390500 | controller | ok: [instance]
2025-09-30 08:48:59.390532 | controller |
2025-09-30 08:48:59.390609 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] *******************************
2025-09-30 08:48:59.390729 | controller | Tuesday 30 September 2025  08:48:59 +0000 (0:00:00.177)       0:04:13.665 *****
2025-09-30 08:49:00.625680 | controller | ok: [instance -> controller-0(192.168.26.58)]
2025-09-30 08:49:00.625728 | controller |
2025-09-30 08:49:00.625737 | controller | TASK [sushy_emulator : Run ssh-keyscan] ****************************************
2025-09-30 08:49:00.625746 | controller | Tuesday 30 September 2025  08:49:00 +0000 (0:00:01.234)       0:04:14.900 *****
2025-09-30 08:49:00.861046 | controller | changed: [instance]
2025-09-30 08:49:01.215217 | controller |
2025-09-30 08:49:01.215251 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************
2025-09-30 08:49:01.215269 | controller | Tuesday 30 September 2025  08:49:00 +0000 (0:00:00.235)       0:04:15.135 *****
2025-09-30 08:49:01.215281 | controller | changed: [instance]
2025-09-30 08:49:01.215318 | controller |
2025-09-30 08:49:01.215379 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:49:01.215478 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.354)       0:04:15.489 *****
2025-09-30 08:49:01.241202 | controller | skipping: [instance]
2025-09-30 08:49:01.241253 | controller |
2025-09-30 08:49:01.241275 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:49:01.241370 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.025)       0:04:15.515 *****
2025-09-30 08:49:01.266100 | controller | skipping: [instance]
2025-09-30 08:49:01.266191 | controller |
2025-09-30 08:49:01.266204 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-09-30 08:49:01.266215 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.024)       0:04:15.540 *****
2025-09-30 08:49:01.288183 | controller | skipping: [instance]
2025-09-30 08:49:01.325233 | controller |
2025-09-30 08:49:01.325274 | controller | TASK [sushy_emulator : Generate list of filtered VMs] **************************
2025-09-30 08:49:01.325282 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.022)       0:04:15.562 *****
2025-09-30 08:49:01.325293 | controller | ok: [instance]
2025-09-30 08:49:01.343181 | controller |
2025-09-30 08:49:01.343203 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] ***************************
2025-09-30 08:49:01.343210 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.036)       0:04:15.599 *****
2025-09-30 08:49:01.343220 | controller | skipping: [instance]
2025-09-30 08:49:01.343419 | controller |
2025-09-30 08:49:01.343430 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ********
2025-09-30 08:49:01.360423 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.018)       0:04:15.618 *****
2025-09-30 08:49:01.360448 | controller | skipping: [instance]
2025-09-30 08:49:01.360552 | controller |
2025-09-30 08:49:01.360563 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] ***************
2025-09-30 08:49:01.360690 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.017)       0:04:15.635 *****
2025-09-30 08:49:01.378624 | controller | skipping: [instance]
2025-09-30 08:49:01.567539 | controller |
2025-09-30 08:49:01.567571 | controller | TASK [sushy_emulator : Generate htpasswd string] *******************************
2025-09-30 08:49:01.567580 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.018)       0:04:15.653 *****
2025-09-30 08:49:01.567590 | controller | changed: [instance]
2025-09-30 08:49:01.567613 | controller |
2025-09-30 08:49:01.567622 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] *********************
2025-09-30 08:49:01.567735 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.188)       0:04:15.842 *****
2025-09-30 08:49:01.601821 | controller | skipping: [instance] => (item=secret)
2025-09-30 08:49:01.602176 | controller | skipping: [instance] => (item=configmap)
2025-09-30 08:49:01.602195 | controller | skipping: [instance] => (item=pod)
2025-09-30 08:49:01.602276 | controller | skipping: [instance] => (item=service)
2025-09-30 08:49:01.602285 | controller | skipping: [instance] => (item=route)
2025-09-30 08:49:01.602293 | controller | skipping: [instance]
2025-09-30 08:49:01.602376 | controller |
2025-09-30 08:49:01.602477 | controller | TASK [sushy_emulator : Write sushy emulator config] ****************************
2025-09-30 08:49:01.602570 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.034)       0:04:15.876 *****
2025-09-30 08:49:01.959763 | controller | changed: [instance]
2025-09-30 08:49:01.959836 | controller |
2025-09-30 08:49:01.959946 | controller | TASK [sushy_emulator : Write htpasswd string to file] **************************
2025-09-30 08:49:01.960055 | controller | Tuesday 30 September 2025  08:49:01 +0000 (0:00:00.357)       0:04:16.234 *****
2025-09-30 08:49:02.304398 | controller | changed: [instance]
2025-09-30 08:49:02.304453 | controller |
2025-09-30 08:49:02.304578 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ********************
2025-09-30 08:49:02.304675 | controller | Tuesday 30 September 2025  08:49:02 +0000 (0:00:00.344)       0:04:16.579 *****
2025-09-30 08:49:02.322667 | controller | skipping: [instance]
2025-09-30 08:49:02.322750 | controller |
2025-09-30 08:49:02.322858 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] ***
2025-09-30 08:49:02.322956 | controller | Tuesday 30 September 2025  08:49:02 +0000 (0:00:00.018)       0:04:16.597 *****
2025-09-30 08:49:02.340786 | controller | skipping: [instance]
2025-09-30 08:49:02.340856 | controller |
2025-09-30 08:49:02.340951 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] *************************
2025-09-30 08:49:02.341048 | controller | Tuesday 30 September 2025  08:49:02 +0000 (0:00:00.018)       0:04:16.615 *****
2025-09-30 08:49:02.368974 | controller | skipping: [instance] => (item=secret)
2025-09-30 08:49:02.369079 | controller | skipping: [instance] => (item=configmap)
2025-09-30 08:49:02.369228 | controller | skipping: [instance] => (item=service)
2025-09-30 08:49:02.369342 | controller | skipping: [instance] => (item=route)
2025-09-30 08:49:02.369448 | controller | skipping: [instance]
2025-09-30 08:49:02.369532 | controller |
2025-09-30 08:49:02.369635 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] **********************
2025-09-30 08:49:02.369735 | controller | Tuesday 30 September 2025  08:49:02 +0000 (0:00:00.028)       0:04:16.643 *****
2025-09-30 08:49:02.387714 | controller | skipping: [instance]
2025-09-30 08:49:02.387813 | controller |
2025-09-30 08:49:02.387946 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-09-30 08:49:02.388066 | controller | Tuesday 30 September 2025  08:49:02 +0000 (0:00:00.018)       0:04:16.662 *****
2025-09-30 08:49:03.630942 | controller | ok: [instance]
2025-09-30 08:49:03.630999 | controller |
2025-09-30 08:49:03.631185 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-09-30 08:49:03.631248 | controller | Tuesday 30 September 2025  08:49:03 +0000 (0:00:01.243)       0:04:17.905 *****
2025-09-30 08:49:03.849559 | controller | changed: [instance]
2025-09-30 08:49:03.849654 | controller |
2025-09-30 08:49:03.849855 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-09-30 08:49:03.877256 | controller | Tuesday 30 September 2025  08:49:03 +0000 (0:00:00.218)       0:04:18.124 *****
2025-09-30 08:49:03.877304 | controller | skipping: [instance]
2025-09-30 08:49:03.877520 | controller |
2025-09-30 08:49:03.877543 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-09-30 08:49:03.901083 | controller | Tuesday 30 September 2025  08:49:03 +0000 (0:00:00.027)       0:04:18.151 *****
2025-09-30 08:49:03.901125 | controller | skipping: [instance]
2025-09-30 08:49:03.901237 | controller |
2025-09-30 08:49:03.901309 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-09-30 08:49:03.901395 | controller | Tuesday 30 September 2025  08:49:03 +0000 (0:00:00.023)       0:04:18.175 *****
2025-09-30 08:49:03.931550 | controller | skipping: [instance]
2025-09-30 08:49:03.931655 | controller |
2025-09-30 08:49:03.931674 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ********************
2025-09-30 08:49:03.931687 | controller | Tuesday 30 September 2025  08:49:03 +0000 (0:00:00.030)       0:04:18.206 *****
2025-09-30 08:49:11.089844 | controller | changed: [instance]
2025-09-30 08:49:11.942522 | controller |
2025-09-30 08:49:11.942559 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] **************
2025-09-30 08:49:11.942569 | controller | Tuesday 30 September 2025  08:49:11 +0000 (0:00:07.153)       0:04:25.359 *****
2025-09-30 08:49:11.942580 | controller | changed: [instance]
2025-09-30 08:49:12.042867 | controller |
2025-09-30 08:49:12.042897 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] *******************
2025-09-30 08:49:12.042912 | controller | Tuesday 30 September 2025  08:49:11 +0000 (0:00:00.854)       0:04:26.213 *****
2025-09-30 08:49:12.042929 | controller |
2025-09-30 08:49:12.042948 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] ***
2025-09-30 08:49:12.043061 | controller | Tuesday 30 September 2025  08:49:12 +0000 (0:00:00.103)       0:04:26.317 *****
2025-09-30 08:49:12.072570 | controller | ok: [instance]
2025-09-30 08:49:12.072624 | controller |
2025-09-30 08:49:12.072771 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-09-30 08:49:12.072904 | controller | Tuesday 30 September 2025  08:49:12 +0000 (0:00:00.029)       0:04:26.347 *****
2025-09-30 08:49:12.099985 | controller | skipping: [instance]
2025-09-30 08:49:12.100079 | controller |
2025-09-30 08:49:12.100219 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-09-30 08:49:12.100363 | controller | Tuesday 30 September 2025  08:49:12 +0000 (0:00:00.027)       0:04:26.375 *****
2025-09-30 08:49:12.123615 | controller | skipping: [instance]
2025-09-30 08:49:12.123688 | controller |
2025-09-30 08:49:12.123917 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] ***
2025-09-30 08:49:13.083793 | controller | Tuesday 30 September 2025  08:49:12 +0000 (0:00:00.023)       0:04:26.398 *****
2025-09-30 08:49:13.083843 | controller | ok: [instance]
2025-09-30 08:49:13.083873 | controller |
2025-09-30 08:49:13.084096 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] ***
2025-09-30 08:49:15.204459 | controller | Tuesday 30 September 2025  08:49:13 +0000 (0:00:00.959)       0:04:27.358 *****
2025-09-30 08:49:15.204500 | controller | ok: [instance] => (item=52b54bc3-3135-4a8b-8fc0-c325d6dc4300)
2025-09-30 08:49:15.204529 | controller | ok: [instance] => (item=ff5726cc-6eef-462c-a5c1-225c9ac6f424)
2025-09-30 08:49:15.204537 | controller |
2025-09-30 08:49:15.204789 | controller | TASK [sushy_emulator : Verify baremetal VM power status] ***********************
2025-09-30 08:49:15.265925 | controller | Tuesday 30 September 2025  08:49:15 +0000 (0:00:02.120)       0:04:29.478 *****
2025-09-30 08:49:15.265974 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-09-30 08:49:15.266012 | controller | ok: [instance] => (item=cifmw-compute-1)
2025-09-30 08:49:15.266200 | controller |
2025-09-30 08:49:15.266454 | controller | PLAY RECAP *********************************************************************
2025-09-30 08:49:15.266476 | controller | instance                   : ok=228  changed=86   unreachable=0    failed=0    skipped=105  rescued=0    ignored=0
2025-09-30 08:49:15.266548 | controller |
2025-09-30 08:49:15.266567 | controller | Tuesday 30 September 2025  08:49:15 +0000 (0:00:00.061)       0:04:29.540 *****
2025-09-30 08:49:15.266576 | controller | ===============================================================================
2025-09-30 08:49:15.266848 | controller | sushy_emulator : Check if router pod is running in openshift-ingress namespace - 101.95s
2025-09-30 08:49:15.267000 | controller | sushy_emulator : Apply Sushy Emulator pod resource --------------------- 60.79s
2025-09-30 08:49:15.267015 | controller | libvirt_manager : Install packages required for using KVM -------------- 11.05s
2025-09-30 08:49:15.267162 | controller | sushy_emulator : Pull Sushy Emulator container image -------------------- 7.15s
2025-09-30 08:49:15.267275 | controller | ci_nmstate : Install required packages on instance ---------------------- 5.66s
2025-09-30 08:49:15.267300 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 3.80s
2025-09-30 08:49:15.267552 | controller | sushy_emulator : Apply Sushy Emulator resources ------------------------- 3.56s
2025-09-30 08:49:15.267889 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 2.49s
2025-09-30 08:49:15.267904 | controller | sushy_emulator : Install required packages ------------------------------ 2.49s
2025-09-30 08:49:15.267913 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 2.12s
2025-09-30 08:49:15.268017 | controller | ci_nmstate : Apply the desidered state on instance ---------------------- 1.91s
2025-09-30 08:49:15.268032 | controller | sushy_emulator : Write sushy emulator resource loop --------------------- 1.78s
2025-09-30 08:49:15.268043 | controller | libvirt_manager : Restart firewalld ------------------------------------- 1.65s
2025-09-30 08:49:15.268051 | controller | dnsmasq : Add/Remove address -------------------------------------------- 1.36s
2025-09-30 08:49:15.268557 | controller | libvirt_manager : Ensure read-only socket is enabled for proxy. --------- 1.35s
2025-09-30 08:49:15.268597 | controller | sushy_emulator : Install required packages ------------------------------ 1.29s
2025-09-30 08:49:15.268605 | controller | dnsmasq : Install needed packages --------------------------------------- 1.25s
2025-09-30 08:49:15.268611 | controller | podman : Ensure podman is installed ------------------------------------- 1.24s
2025-09-30 08:49:15.268616 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.23s
2025-09-30 08:49:15.268624 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.14s
2025-09-30 08:49:15.349899 | controller | INFO     Running default > cleanup
2025-09-30 08:49:15.350399 | controller | WARNING  Skipping, cleanup playbook not configured.
2025-09-30 08:49:15.351042 | controller | INFO     Writing /tmp/report.html report.
2025-09-30 08:49:15.691394 | [controller] Waiting on logger
2025-09-30 08:49:20.818356 | [controller] Waiting on logger
2025-09-30 08:49:31.250393 | [controller] Waiting on logger
2025-09-30 08:49:41.682378 | [controller] Waiting on logger
2025-09-30 08:49:45.436900 | [Zuul] Log Stream did not terminate
2025-09-30 08:49:45.437110 | controller | changed
2025-09-30 08:49:45.464561 | 
2025-09-30 08:49:45.464620 | PLAY RECAP
2025-09-30 08:49:45.464658 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 08:49:45.464680 | 
2025-09-30 08:49:45.537738 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-30 08:49:45.538525 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-30 08:49:46.076326 | 
2025-09-30 08:49:46.076450 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-09-30 08:49:46.097639 | 
2025-09-30 08:49:46.097735 | TASK [Filter out host if needed]
2025-09-30 08:49:46.106619 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-09-30 08:49:46.111309 | 
2025-09-30 08:49:46.111381 | TASK [Ensure file is present]
2025-09-30 08:49:46.474713 | controller | ok
2025-09-30 08:49:46.481905 | 
2025-09-30 08:49:46.481995 | TASK [Manage molecule report file]
2025-09-30 08:49:46.502481 | [controller] Waiting on logger
2025-09-30 08:49:55.826439 | [controller] Waiting on logger
2025-09-30 08:50:06.258462 | [controller] Waiting on logger
2025-09-30 08:50:16.690375 | [controller] Waiting on logger
2025-09-30 08:50:16.866522 | [Zuul] Log Stream did not terminate
2025-09-30 08:50:16.866719 | controller | changed
2025-09-30 08:50:16.872314 | 
2025-09-30 08:50:16.872390 | TASK [Check if we get ci-framework-data basedir]
2025-09-30 08:50:17.135508 | controller | ok
2025-09-30 08:50:17.140972 | 
2025-09-30 08:50:17.141037 | TASK [Create ci-framework-data log directory for zuul]
2025-09-30 08:50:17.546113 | controller | changed
2025-09-30 08:50:17.551754 | 
2025-09-30 08:50:17.551831 | TASK [Copy ci-framework interesting files]
2025-09-30 08:50:22.586379 | controller | changed
2025-09-30 08:50:22.592604 | 
2025-09-30 08:50:22.592677 | TASK [Get SELinux listing]
2025-09-30 08:50:23.666487 | [controller] Waiting on logger
2025-09-30 08:50:35.058661 | [controller] Waiting on logger
2025-09-30 08:50:45.491592 | [controller] Waiting on logger
2025-09-30 08:50:52.876975 | [Zuul] Log Stream did not terminate
2025-09-30 08:50:52.877218 | controller | changed
2025-09-30 08:50:52.883027 | 
2025-09-30 08:50:52.883102 | TASK [Generate log index]
2025-09-30 08:50:54.018064 | controller | changed
2025-09-30 08:50:54.023045 | 
2025-09-30 08:50:54.023114 | TASK [Get some env related data]
2025-09-30 08:50:54.834745 | [controller] Waiting on logger
2025-09-30 08:50:59.049923 | controller | changed
2025-09-30 08:50:59.054985 | 
2025-09-30 08:50:59.055045 | TASK [Generate list of logs to collect in home directory]
2025-09-30 08:50:59.425765 | controller | ok: All paths examined
2025-09-30 08:50:59.430868 | 
2025-09-30 08:50:59.431011 | LOOP [Copy logs from home directory]
2025-09-30 08:50:59.967081 | controller | changed:
2025-09-30 08:50:59.967333 | controller | {
2025-09-30 08:50:59.967361 | controller |   "atime": 1743544925.4788878,
2025-09-30 08:50:59.967381 | controller |   "ctime": 1743545329.1409318,
2025-09-30 08:50:59.967398 | controller |   "dev": 64513,
2025-09-30 08:50:59.967414 | controller |   "gid": 1000,
2025-09-30 08:50:59.967440 | controller |   "gr_name": "zuul",
2025-09-30 08:50:59.967458 | controller |   "inode": 4518807,
2025-09-30 08:50:59.967472 | controller |   "isblk": false,
2025-09-30 08:50:59.967486 | controller |   "ischr": false,
2025-09-30 08:50:59.967499 | controller |   "isdir": false,
2025-09-30 08:50:59.967513 | controller |   "isfifo": false,
2025-09-30 08:50:59.967527 | controller |   "isgid": false,
2025-09-30 08:50:59.967552 | controller |   "islnk": false,
2025-09-30 08:50:59.967568 | controller |   "isreg": true,
2025-09-30 08:50:59.967583 | controller |   "issock": false,
2025-09-30 08:50:59.967596 | controller |   "isuid": false,
2025-09-30 08:50:59.967610 | controller |   "mode": "0644",
2025-09-30 08:50:59.967623 | controller |   "mtime": 1743545329.1409318,
2025-09-30 08:50:59.967638 | controller |   "nlink": 1,
2025-09-30 08:50:59.967653 | controller |   "path": "/home/zuul/crc-setup.log",
2025-09-30 08:50:59.967670 | controller |   "pw_name": "zuul",
2025-09-30 08:50:59.967686 | controller |   "rgrp": true,
2025-09-30 08:50:59.967700 | controller |   "roth": true,
2025-09-30 08:50:59.967714 | controller |   "rusr": true,
2025-09-30 08:50:59.967728 | controller |   "size": 4108,
2025-09-30 08:50:59.967741 | controller |   "uid": 1000,
2025-09-30 08:50:59.967754 | controller |   "wgrp": false,
2025-09-30 08:50:59.967768 | controller |   "woth": false,
2025-09-30 08:50:59.967781 | controller |   "wusr": true,
2025-09-30 08:50:59.967795 | controller |   "xgrp": false,
2025-09-30 08:50:59.967808 | controller |   "xoth": false,
2025-09-30 08:50:59.967822 | controller |   "xusr": false
2025-09-30 08:50:59.967835 | controller | }
2025-09-30 08:51:00.484205 | controller | changed:
2025-09-30 08:51:00.484303 | controller | {
2025-09-30 08:51:00.484330 | controller |   "atime": 1743545331.0429637,
2025-09-30 08:51:00.484350 | controller |   "ctime": 1743545842.0111232,
2025-09-30 08:51:00.484366 | controller |   "dev": 64513,
2025-09-30 08:51:00.484382 | controller |   "gid": 1000,
2025-09-30 08:51:00.484398 | controller |   "gr_name": "zuul",
2025-09-30 08:51:00.484412 | controller |   "inode": 4194437,
2025-09-30 08:51:00.484427 | controller |   "isblk": false,
2025-09-30 08:51:00.484456 | controller |   "ischr": false,
2025-09-30 08:51:00.484472 | controller |   "isdir": false,
2025-09-30 08:51:00.484487 | controller |   "isfifo": false,
2025-09-30 08:51:00.484502 | controller |   "isgid": false,
2025-09-30 08:51:00.484516 | controller |   "islnk": false,
2025-09-30 08:51:00.484531 | controller |   "isreg": true,
2025-09-30 08:51:00.484545 | controller |   "issock": false,
2025-09-30 08:51:00.484558 | controller |   "isuid": false,
2025-09-30 08:51:00.484571 | controller |   "mode": "0644",
2025-09-30 08:51:00.484585 | controller |   "mtime": 1743545842.0111232,
2025-09-30 08:51:00.484598 | controller |   "nlink": 1,
2025-09-30 08:51:00.484612 | controller |   "path": "/home/zuul/crc-start.log",
2025-09-30 08:51:00.484625 | controller |   "pw_name": "zuul",
2025-09-30 08:51:00.484639 | controller |   "rgrp": true,
2025-09-30 08:51:00.484653 | controller |   "roth": true,
2025-09-30 08:51:00.484846 | controller |   "rusr": true,
2025-09-30 08:51:00.484881 | controller |   "size": 4023,
2025-09-30 08:51:00.484903 | controller |   "uid": 1000,
2025-09-30 08:51:00.484941 | controller |   "wgrp": false,
2025-09-30 08:51:00.484960 | controller |   "woth": false,
2025-09-30 08:51:00.484975 | controller |   "wusr": true,
2025-09-30 08:51:00.484989 | controller |   "xgrp": false,
2025-09-30 08:51:00.485003 | controller |   "xoth": false,
2025-09-30 08:51:00.485016 | controller |   "xusr": false
2025-09-30 08:51:00.485030 | controller | }
2025-09-30 08:51:01.042446 | controller | changed:
2025-09-30 08:51:01.042547 | controller | {
2025-09-30 08:51:01.042572 | controller |   "atime": 1759221627.8274047,
2025-09-30 08:51:01.042591 | controller |   "ctime": 1759221643.3983734,
2025-09-30 08:51:01.042609 | controller |   "dev": 64513,
2025-09-30 08:51:01.042624 | controller |   "gid": 1000,
2025-09-30 08:51:01.042639 | controller |   "gr_name": "zuul",
2025-09-30 08:51:01.042654 | controller |   "inode": 4340282,
2025-09-30 08:51:01.042668 | controller |   "isblk": false,
2025-09-30 08:51:01.042682 | controller |   "ischr": false,
2025-09-30 08:51:01.042696 | controller |   "isdir": false,
2025-09-30 08:51:01.042710 | controller |   "isfifo": false,
2025-09-30 08:51:01.042725 | controller |   "isgid": false,
2025-09-30 08:51:01.042745 | controller |   "islnk": false,
2025-09-30 08:51:01.042762 | controller |   "isreg": true,
2025-09-30 08:51:01.042776 | controller |   "issock": false,
2025-09-30 08:51:01.042793 | controller |   "isuid": false,
2025-09-30 08:51:01.042808 | controller |   "mode": "0644",
2025-09-30 08:51:01.042823 | controller |   "mtime": 1759221643.3983734,
2025-09-30 08:51:01.042838 | controller |   "nlink": 1,
2025-09-30 08:51:01.042852 | controller |   "path": "/home/zuul/ansible.log",
2025-09-30 08:51:01.042866 | controller |   "pw_name": "zuul",
2025-09-30 08:51:01.042880 | controller |   "rgrp": true,
2025-09-30 08:51:01.042893 | controller |   "roth": true,
2025-09-30 08:51:01.042935 | controller |   "rusr": true,
2025-09-30 08:51:01.042961 | controller |   "size": 6749,
2025-09-30 08:51:01.042978 | controller |   "uid": 1000,
2025-09-30 08:51:01.042994 | controller |   "wgrp": false,
2025-09-30 08:51:01.043008 | controller |   "woth": false,
2025-09-30 08:51:01.043022 | controller |   "wusr": true,
2025-09-30 08:51:01.043036 | controller |   "xgrp": false,
2025-09-30 08:51:01.043050 | controller |   "xoth": false,
2025-09-30 08:51:01.043063 | controller |   "xusr": false
2025-09-30 08:51:01.043077 | controller | }
2025-09-30 08:51:01.052554 | 
2025-09-30 08:51:01.052674 | TASK [Copy crio stats log file]
2025-09-30 08:51:01.066558 | controller | skipping: Conditional result was False
2025-09-30 08:51:01.073497 | 
2025-09-30 08:51:01.073597 | TASK [Get SELinux related data]
2025-09-30 08:51:05.266337 | [controller] Waiting on logger
2025-09-30 08:51:06.101289 | controller | ERROR
2025-09-30 08:51:06.101508 | controller | {
2025-09-30 08:51:06.101542 | controller |   "delta": "0:00:00.011086",
2025-09-30 08:51:06.101564 | controller |   "end": "2025-09-30 08:51:01.349764",
2025-09-30 08:51:06.101582 | controller |   "msg": "non-zero return code",
2025-09-30 08:51:06.101598 | controller |   "rc": 1,
2025-09-30 08:51:06.101614 | controller |   "start": "2025-09-30 08:51:01.338678"
2025-09-30 08:51:06.101629 | controller | }
2025-09-30 08:51:06.101654 | controller | ERROR: Ignoring Errors
2025-09-30 08:51:06.106866 | 
2025-09-30 08:51:06.106945 | TASK [Create system configuration directory]
2025-09-30 08:51:06.358803 | controller | changed
2025-09-30 08:51:06.364074 | 
2025-09-30 08:51:06.364148 | TASK [Get some of the system configurations]
2025-09-30 08:51:06.384581 | [controller] Waiting on logger
2025-09-30 08:51:23.890448 | [controller] Waiting on logger
2025-09-30 08:51:26.066422 | [controller] Waiting on logger
2025-09-30 08:51:35.524015 | controller | changed
2025-09-30 08:51:35.529839 | 
2025-09-30 08:51:35.529923 | TASK [Copy generated documentation if available]
2025-09-30 08:51:35.543106 | controller | skipping: Conditional result was False
2025-09-30 08:51:35.548302 | 
2025-09-30 08:51:35.548364 | TASK [Copy generated AsciiDoc documentation if available]
2025-09-30 08:51:35.560978 | controller | skipping: Conditional result was False
2025-09-30 08:51:35.566122 | 
2025-09-30 08:51:35.566184 | TASK [Compress logs bigger than 2MB]
2025-09-30 08:51:38.418425 | [controller] Waiting on logger
2025-09-30 08:51:40.592276 | controller | changed
2025-09-30 08:51:40.597600 | 
2025-09-30 08:51:40.597663 | TASK [Copy files from workspace on node]
2025-09-30 08:51:40.615639 | controller | ok
2025-09-30 08:51:40.638405 | 
2025-09-30 08:51:40.638489 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 08:51:40.662080 | controller | skipping: Conditional result was False
2025-09-30 08:51:40.667944 | 
2025-09-30 08:51:40.668014 | TASK [fetch-output : Set log path for single node]
2025-09-30 08:51:40.696180 | controller | ok
2025-09-30 08:51:40.701201 | 
2025-09-30 08:51:40.701268 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 08:51:40.900081 | controller -> localhost | ok: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/logs"
2025-09-30 08:51:40.900350 | controller -> localhost | changed: All items complete
2025-09-30 08:51:40.900386 | 
2025-09-30 08:51:41.084312 | controller -> localhost | changed: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/artifacts"
2025-09-30 08:51:41.267936 | controller -> localhost | changed: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/docs"
2025-09-30 08:51:41.280236 | 
2025-09-30 08:51:41.280328 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 08:51:41.904979 | controller | changed:
2025-09-30 08:51:41.905196 | controller | .d..t...... ./
2025-09-30 08:51:41.905226 | controller | >f+++++++++ README.html
2025-09-30 08:51:41.905249 | controller | >f+++++++++ ansible-execution.log
2025-09-30 08:51:41.905269 | controller | >f+++++++++ ansible.log
2025-09-30 08:51:41.905288 | controller | >f+++++++++ crc-setup.log
2025-09-30 08:51:41.905307 | controller | >f+++++++++ crc-start.log
2025-09-30 08:51:41.905325 | controller | >f+++++++++ dmesg.log
2025-09-30 08:51:41.905343 | controller | >f+++++++++ installed-pkgs.log
2025-09-30 08:51:41.905361 | controller | >f+++++++++ python.log
2025-09-30 08:51:41.905378 | controller | >f+++++++++ registries.conf
2025-09-30 08:51:41.905396 | controller | >f+++++++++ report.html
2025-09-30 08:51:41.905413 | controller | >f+++++++++ selinux-denials.log
2025-09-30 08:51:41.905430 | controller | >f+++++++++ selinux-listing.log
2025-09-30 08:51:41.905448 | controller | cd+++++++++ ci-framework-data/
2025-09-30 08:51:41.905478 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-09-30 08:51:41.905497 | controller | >f+++++++++ ci-framework-data/artifacts/debug_cifmw_libvirt_manager_layout.yml
2025-09-30 08:51:41.905515 | controller | >f+++++++++ ci-framework-data/artifacts/debug_network_data.yml
2025-09-30 08:51:41.905533 | controller | >f+++++++++ ci-framework-data/artifacts/debug_pub_net_value.txt
2025-09-30 08:51:41.905550 | controller | >f+++++++++ ci-framework-data/artifacts/interfaces-info.yml
2025-09-30 08:51:41.905567 | controller | >f+++++++++ ci-framework-data/artifacts/libvirt-uuids.yml
2025-09-30 08:51:41.905584 | controller | >f+++++++++ ci-framework-data/artifacts/net-map-def-patch.yml
2025-09-30 08:51:41.905601 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-09-30 08:51:41.905618 | controller | cd+++++++++ ci-framework-data/artifacts/nmstate/
2025-09-30 08:51:41.905635 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-final-state.yaml
2025-09-30 08:51:41.905652 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-state.yaml
2025-09-30 08:51:41.905670 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-09-30 08:51:41.905687 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-09-30 08:51:41.905704 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-09-30 08:51:41.905720 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-09-30 08:51:41.905737 | controller | cd+++++++++ ci-framework-data/artifacts/sushy_emulator/
2025-09-30 08:51:41.905753 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/.htpasswd
2025-09-30 08:51:41.905769 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/config.conf
2025-09-30 08:51:41.905785 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/configmap.yaml
2025-09-30 08:51:41.905801 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/known_hosts
2025-09-30 08:51:41.905817 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/pod.yaml
2025-09-30 08:51:41.905834 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/route.yaml
2025-09-30 08:51:41.905851 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/secret.yaml
2025-09-30 08:51:41.905868 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/service.yaml
2025-09-30 08:51:41.905885 | controller | cd+++++++++ ci-framework-data/logs/
2025-09-30 08:51:41.905903 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-09-30 08:51:41.905939 | controller | cd+++++++++ registries.conf.d/
2025-09-30 08:51:41.905963 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-09-30 08:51:41.905981 | controller | cd+++++++++ system-config/
2025-09-30 08:51:41.905997 | controller | cd+++++++++ system-config/libvirt/
2025-09-30 08:51:41.906013 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-09-30 08:51:41.906031 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-09-30 08:51:41.906048 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-09-30 08:51:41.906064 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-09-30 08:51:41.906081 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-09-30 08:51:41.906097 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-09-30 08:51:41.906114 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-09-30 08:51:41.906130 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-09-30 08:51:41.906146 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-09-30 08:51:41.906162 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-09-30 08:51:41.906178 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-09-30 08:51:41.906194 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-09-30 08:51:41.906213 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-09-30 08:51:41.906230 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-09-30 08:51:41.906247 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-09-30 08:51:41.906263 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-09-30 08:51:42.361596 | controller | changed: .d..t...... ./
2025-09-30 08:51:42.784537 | controller | changed: .d..t...... ./
2025-09-30 08:51:42.796766 | 
2025-09-30 08:51:42.796877 | TASK [Return artifact to Zuul]
2025-09-30 08:51:42.825821 | controller | ok
2025-09-30 08:51:42.844350 | 
2025-09-30 08:51:42.844403 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-09-30 08:51:42.844520 | 
2025-09-30 08:51:42.844550 | PLAY RECAP
2025-09-30 08:51:42.844589 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-09-30 08:51:42.844610 | 
2025-09-30 08:51:42.927476 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-30 08:51:42.928254 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 08:51:43.438358 | 
2025-09-30 08:51:43.438473 | PLAY [all]
2025-09-30 08:51:43.456784 | 
2025-09-30 08:51:43.456858 | TASK [include_role : fetch-output]
2025-09-30 08:51:43.485093 | controller | ok
2025-09-30 08:51:43.501428 | 
2025-09-30 08:51:43.501525 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 08:51:43.545443 | controller | skipping: Conditional result was False
2025-09-30 08:51:43.550994 | 
2025-09-30 08:51:43.551067 | TASK [fetch-output : Set log path for single node]
2025-09-30 08:51:43.579567 | controller | ok
2025-09-30 08:51:43.584470 | 
2025-09-30 08:51:43.584544 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 08:51:43.907334 | controller -> localhost | ok: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/logs"
2025-09-30 08:51:44.091254 | controller -> localhost | ok: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/artifacts"
2025-09-30 08:51:44.269981 | controller -> localhost | ok: "/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/docs"
2025-09-30 08:51:44.283672 | 
2025-09-30 08:51:44.283742 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 08:51:44.862997 | controller | ok
2025-09-30 08:51:44.863185 | controller | ok: All items complete
2025-09-30 08:51:44.863216 | 
2025-09-30 08:51:45.299117 | controller | ok
2025-09-30 08:51:45.731750 | controller | ok
2025-09-30 08:51:45.744629 | 
2025-09-30 08:51:45.744702 | TASK [include_role : fetch-output-openshift]
2025-09-30 08:51:45.758548 | controller | skipping: Conditional result was False
2025-09-30 08:51:45.764143 | 
2025-09-30 08:51:45.764215 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 08:51:46.109297 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006383
2025-09-30 08:51:46.297226 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006277
2025-09-30 08:51:46.328894 | 
2025-09-30 08:51:46.329004 | PLAY [all]
2025-09-30 08:51:46.342807 | 
2025-09-30 08:51:46.342875 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-30 08:51:46.808446 | controller | changed
2025-09-30 08:51:46.829767 | 
2025-09-30 08:51:46.829841 | PLAY RECAP
2025-09-30 08:51:46.829886 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 08:51:46.829929 | 
2025-09-30 08:51:46.906345 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 08:51:46.907123 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-30 08:51:47.464532 | 
2025-09-30 08:51:47.464692 | PLAY [localhost]
2025-09-30 08:51:47.482691 | 
2025-09-30 08:51:47.482804 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 08:51:47.815064 | localhost | changed
2025-09-30 08:51:47.819631 | 
2025-09-30 08:51:47.819721 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 08:51:47.847144 | localhost | ok
2025-09-30 08:51:47.855079 | 
2025-09-30 08:51:47.855147 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-30 08:51:48.166740 | localhost | changed
2025-09-30 08:51:48.172529 | 
2025-09-30 08:51:48.172603 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-30 08:51:48.717472 | localhost | changed
2025-09-30 08:51:48.722353 | 
2025-09-30 08:51:48.722420 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-30 08:51:49.064233 | localhost | Identity added: /var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/tmp/ansible.54y388bo (/var/lib/zuul/builds/ff41629a8ef04166b4c5f9298a576faa/work/tmp/ansible.54y388bo)
2025-09-30 08:51:49.064412 | localhost | ok: Runtime: 0:00:00.007124
2025-09-30 08:51:49.068615 | 
2025-09-30 08:51:49.068684 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-30 08:51:49.300272 | localhost | ok: Runtime: 0:00:00.005002
2025-09-30 08:51:49.304956 | 
2025-09-30 08:51:49.305026 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-30 08:51:49.353495 | localhost | changed
2025-09-30 08:51:49.357769 | 
2025-09-30 08:51:49.357837 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-30 08:51:49.689405 | localhost | changed
2025-09-30 08:51:49.708563 | 
2025-09-30 08:51:49.708640 | PLAY [localhost]
2025-09-30 08:51:49.719814 | 
2025-09-30 08:51:49.719879 | TASK [Generate bulk log download script]
2025-09-30 08:51:49.737810 | localhost | ok
2025-09-30 08:51:49.748858 | 
2025-09-30 08:51:49.748951 | TASK [local-log-download : Check API endpoint is defined]
2025-09-30 08:51:49.775826 | localhost | ok: All assertions passed
2025-09-30 08:51:49.780296 | 
2025-09-30 08:51:49.780378 | TASK [local-log-download : Create download script]
2025-09-30 08:51:50.128146 | localhost -> localhost | changed
2025-09-30 08:51:50.137405 | 
2025-09-30 08:51:50.137485 | TASK [Register quick-download link]
2025-09-30 08:51:50.154443 | localhost | ok
2025-09-30 08:51:50.188799 | 
2025-09-30 08:51:50.188885 | PLAY [logserver.rdoproject.org]
2025-09-30 08:51:50.198528 | 
2025-09-30 08:51:50.198588 | TASK [Set zuul-log-path fact]
2025-09-30 08:51:50.214041 | logserver.rdoproject.org | ok
2025-09-30 08:51:50.222887 | 
2025-09-30 08:51:50.222988 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 08:51:50.238146 | logserver.rdoproject.org | ok
2025-09-30 08:51:50.243191 | 
2025-09-30 08:51:50.243254 | TASK [upload-logs : Create log directories]
2025-09-30 08:51:51.959790 | logserver.rdoproject.org | changed
2025-09-30 08:51:51.962959 | 
2025-09-30 08:51:51.963026 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-30 08:51:52.179595 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004339
2025-09-30 08:51:52.185205 | 
2025-09-30 08:51:52.185280 | TASK [upload-logs : Upload logs to log server]
2025-09-30 08:51:53.760529 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-30 08:51:53.763482 | 
2025-09-30 08:51:53.763548 | LOOP [upload-logs : Compress console log and json output]
2025-09-30 08:51:53.800521 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 08:51:53.808376 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 08:51:53.821675 | 
2025-09-30 08:51:53.821787 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-30 08:51:53.857901 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 08:51:53.858117 | 
2025-09-30 08:51:53.860828 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 08:51:53.869167 | 
2025-09-30 08:51:53.869276 | LOOP [upload-logs : Upload console log and json output]