2025-10-02 19:57:43.370224 | Job console starting... 2025-10-02 19:57:43.608669 | Updating repositories 2025-10-02 19:57:44.367663 | Preparing job workspace 2025-10-02 19:57:53.244485 | Running Ansible setup... 2025-10-02 19:57:58.364541 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 19:57:59.475443 | 2025-10-02 19:57:59.475845 | PLAY [localhost] 2025-10-02 19:57:59.486144 | 2025-10-02 19:57:59.486219 | TASK [Gathering Facts] 2025-10-02 19:58:00.822314 | localhost | ok 2025-10-02 19:58:00.847201 | 2025-10-02 19:58:00.847373 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-02 19:58:01.447459 | localhost -> localhost | changed 2025-10-02 19:58:01.453200 | 2025-10-02 19:58:01.453274 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-02 19:58:02.493233 | localhost -> localhost | changed 2025-10-02 19:58:02.514685 | 2025-10-02 19:58:02.514778 | TASK [Setup log path fact] 2025-10-02 19:58:02.535859 | localhost | ok 2025-10-02 19:58:02.546735 | 2025-10-02 19:58:02.546812 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 19:58:02.574516 | localhost | ok 2025-10-02 19:58:02.583307 | 2025-10-02 19:58:02.583436 | TASK [emit-job-header : Print job information] 2025-10-02 19:58:02.621364 | # Job Information 2025-10-02 19:58:02.621533 | Ansible Version: 2.15.12 2025-10-02 19:58:02.621564 | Job: cifmw-molecule-sushy_emulator 2025-10-02 19:58:02.621588 | Pipeline: github-check 2025-10-02 19:58:02.621627 | Executor: ibm-bm3-ze.softwarefactory-project.io 2025-10-02 19:58:02.621649 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362 2025-10-02 19:58:02.621671 | Log URL (when completed): https://logserver.rdoproject.org/710/rdoproject.org/710274db8c2a411badea6a8fba077a23/ 2025-10-02 19:58:02.621693 | Event ID: 1aeabe40-9fc9-11f0-9f57-122990aafcb1 2025-10-02 19:58:02.625270 | 2025-10-02 19:58:02.625337 | LOOP [emit-job-header : Print node information] 2025-10-02 19:58:02.760422 | localhost | ok: 2025-10-02 19:58:02.760570 | localhost | # Node Information 2025-10-02 19:58:02.760609 | localhost | Inventory Hostname: controller 2025-10-02 19:58:02.760636 | localhost | Hostname: np0005467320 2025-10-02 19:58:02.760657 | localhost | Username: zuul 2025-10-02 19:58:02.760678 | localhost | Distro: CentOS 9 2025-10-02 19:58:02.760696 | localhost | Provider: ibm-bm3-nodepool 2025-10-02 19:58:02.760713 | localhost | Region: regionOne 2025-10-02 19:58:02.760730 | localhost | Label: centos-9-stream-crc-2-48-0-xl-ibm 2025-10-02 19:58:02.760747 | localhost | Product Name: OpenStack Compute 2025-10-02 19:58:02.760764 | localhost | Interface IP: 192.168.25.229 2025-10-02 19:58:02.793650 | 2025-10-02 19:58:02.793736 | PLAY [all] 2025-10-02 19:58:02.805045 | 2025-10-02 19:58:02.805109 | TASK [Gather network facts] 2025-10-02 19:58:03.290980 | controller | ok 2025-10-02 19:58:03.307264 | 2025-10-02 19:58:03.307330 | TASK [include_role : start-zuul-console] 2025-10-02 19:58:03.325155 | controller | ok 2025-10-02 19:58:03.337959 | 2025-10-02 19:58:03.338024 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-02 19:58:03.763173 | controller | ok 2025-10-02 19:58:03.772829 | 2025-10-02 19:58:03.772896 | TASK [include_role : add-build-sshkey] 2025-10-02 19:58:03.790504 | controller | ok 2025-10-02 19:58:03.804319 | 2025-10-02 19:58:03.804415 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-02 19:58:04.019825 | controller -> localhost | ok 2025-10-02 19:58:04.025476 | 2025-10-02 19:58:04.025564 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-02 19:58:04.043501 | controller | ok 2025-10-02 19:58:04.056206 | controller | included: /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-02 19:58:04.062048 | 2025-10-02 19:58:04.062111 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-02 19:58:04.636814 | controller -> localhost | Generating public/private rsa key pair. 2025-10-02 19:58:04.637023 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/710274db8c2a411badea6a8fba077a23_id_rsa. 2025-10-02 19:58:04.637060 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/710274db8c2a411badea6a8fba077a23_id_rsa.pub. 2025-10-02 19:58:04.637093 | controller -> localhost | The key fingerprint is: 2025-10-02 19:58:04.637119 | controller -> localhost | SHA256:zbxm3o5Zv6bDgocC4H891vIeVLYKQbi+ZcCdeD+hOXc zuul-build-sshkey 2025-10-02 19:58:04.637143 | controller -> localhost | The key's randomart image is: 2025-10-02 19:58:04.637164 | controller -> localhost | +---[RSA 3072]----+ 2025-10-02 19:58:04.637183 | controller -> localhost | | .. | 2025-10-02 19:58:04.637203 | controller -> localhost | | .. | 2025-10-02 19:58:04.637222 | controller -> localhost | | . +.. o | 2025-10-02 19:58:04.637240 | controller -> localhost | | . = +=.o . | 2025-10-02 19:58:04.637258 | controller -> localhost | | . . . oS+=.. | 2025-10-02 19:58:04.637284 | controller -> localhost | | . . . *o+oE | 2025-10-02 19:58:04.637303 | controller -> localhost | | . . = **+. | 2025-10-02 19:58:04.637323 | controller -> localhost | | . + B++*o.. | 2025-10-02 19:58:04.637341 | controller -> localhost | | . o **o++o. | 2025-10-02 19:58:04.637359 | controller -> localhost | +----[SHA256]-----+ 2025-10-02 19:58:04.637434 | controller -> localhost | ok: Runtime: 0:00:00.140684 2025-10-02 19:58:04.648232 | 2025-10-02 19:58:04.648309 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-02 19:58:04.700507 | controller | ok 2025-10-02 19:58:04.730841 | controller | included: /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-02 19:58:04.742322 | 2025-10-02 19:58:04.744429 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-02 19:58:04.789581 | controller | skipping: Conditional result was False 2025-10-02 19:58:04.798053 | 2025-10-02 19:58:04.798122 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-02 19:58:05.495801 | controller | changed 2025-10-02 19:58:05.500952 | 2025-10-02 19:58:05.501289 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-02 19:58:05.773315 | controller | ok 2025-10-02 19:58:05.778646 | 2025-10-02 19:58:05.778731 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-02 19:58:07.063033 | controller | changed 2025-10-02 19:58:07.069289 | 2025-10-02 19:58:07.069370 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-02 19:58:08.418080 | controller | changed 2025-10-02 19:58:08.423156 | 2025-10-02 19:58:08.423222 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-02 19:58:08.462139 | controller | skipping: Conditional result was False 2025-10-02 19:58:08.467795 | 2025-10-02 19:58:08.467863 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-02 19:58:08.880838 | controller -> localhost | changed 2025-10-02 19:58:08.890353 | 2025-10-02 19:58:08.890824 | TASK [add-build-sshkey : Add back temp key] 2025-10-02 19:58:09.205750 | controller -> localhost | Identity added: /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/710274db8c2a411badea6a8fba077a23_id_rsa (zuul-build-sshkey) 2025-10-02 19:58:09.205926 | controller -> localhost | ok: Runtime: 0:00:00.007377 2025-10-02 19:58:09.211579 | 2025-10-02 19:58:09.211665 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-02 19:58:09.627783 | controller | ok 2025-10-02 19:58:09.633611 | 2025-10-02 19:58:09.633737 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-02 19:58:09.657412 | controller | skipping: Conditional result was False 2025-10-02 19:58:09.669239 | 2025-10-02 19:58:09.669342 | TASK [include_role : validate-host] 2025-10-02 19:58:09.689199 | controller | ok 2025-10-02 19:58:09.731569 | 2025-10-02 19:58:09.731662 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-02 19:58:09.759900 | controller | ok 2025-10-02 19:58:09.764585 | 2025-10-02 19:58:09.764841 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-02 19:58:10.025670 | controller -> localhost | ok 2025-10-02 19:58:10.032623 | 2025-10-02 19:58:10.032692 | TASK [validate-host : Collect information about the host] 2025-10-02 19:58:10.764874 | controller | ok 2025-10-02 19:58:10.774834 | 2025-10-02 19:58:10.774923 | TASK [validate-host : Sanitize hostname] 2025-10-02 19:58:10.823900 | controller | ok 2025-10-02 19:58:10.838508 | 2025-10-02 19:58:10.838580 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-02 19:58:11.514353 | controller -> localhost | changed 2025-10-02 19:58:11.520349 | 2025-10-02 19:58:11.520458 | TASK [validate-host : Collect information about zuul worker] 2025-10-02 19:58:12.088580 | controller | ok 2025-10-02 19:58:12.094370 | 2025-10-02 19:58:12.094480 | TASK [validate-host : Write out all zuul information for each host] 2025-10-02 19:58:12.566100 | controller -> localhost | changed 2025-10-02 19:58:12.576895 | 2025-10-02 19:58:12.576977 | TASK [include_role : prepare-workspace-openshift] 2025-10-02 19:58:12.601131 | controller | skipping: Conditional result was False 2025-10-02 19:58:12.606996 | 2025-10-02 19:58:12.607068 | TASK [include_role : remove-zuul-sshkey] 2025-10-02 19:58:12.619761 | controller | skipping: Conditional result was False 2025-10-02 19:58:12.625646 | 2025-10-02 19:58:12.625714 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 19:58:12.897430 | controller | ok: "logs" 2025-10-02 19:58:12.897663 | controller | ok: All items complete 2025-10-02 19:58:12.897694 | 2025-10-02 19:58:13.141815 | controller | ok: "artifacts" 2025-10-02 19:58:13.392358 | controller | ok: "docs" 2025-10-02 19:58:13.400124 | 2025-10-02 19:58:13.400233 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 19:58:13.715084 | controller | changed: "logs" 2025-10-02 19:58:13.948216 | controller | changed: "artifacts" 2025-10-02 19:58:14.190939 | controller | changed: "docs" 2025-10-02 19:58:14.235991 | 2025-10-02 19:58:14.236066 | PLAY RECAP 2025-10-02 19:58:14.236112 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-02 19:58:14.236143 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 19:58:14.236164 | 2025-10-02 19:58:14.322500 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 19:58:14.323196 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master] 2025-10-02 19:58:14.915899 | 2025-10-02 19:58:14.916020 | PLAY [all] 2025-10-02 19:58:14.935841 | 2025-10-02 19:58:14.935915 | TASK [mirror-info-fork : Set mirror_fqdn if not defined] 2025-10-02 19:58:15.015011 | controller | ok 2025-10-02 19:58:15.019906 | 2025-10-02 19:58:15.019985 | TASK [mirror-info-fork : Create /etc/ci] 2025-10-02 19:58:15.513284 | controller | changed 2025-10-02 19:58:15.518752 | 2025-10-02 19:58:15.518825 | TASK [mirror-info-fork : Install ci_mirror script] 2025-10-02 19:58:16.859618 | controller | changed 2025-10-02 19:58:16.870872 | 2025-10-02 19:58:16.870955 | LOOP [add-authorized-keys : Enable access via build key on all nodes] 2025-10-02 19:58:17.353272 | controller | changed: 2025-10-02 19:58:17.353457 | controller | { 2025-10-02 19:58:17.353493 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com" 2025-10-02 19:58:17.353525 | controller | } 2025-10-02 19:58:17.648555 | controller | changed: 2025-10-02 19:58:17.648644 | controller | { 2025-10-02 19:58:17.648675 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com" 2025-10-02 19:58:17.648698 | controller | } 2025-10-02 19:58:17.947802 | controller | changed: 2025-10-02 19:58:17.947879 | controller | { 2025-10-02 19:58:17.947907 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com" 2025-10-02 19:58:17.947929 | controller | } 2025-10-02 19:58:18.300851 | controller | changed: 2025-10-02 19:58:18.300939 | controller | { 2025-10-02 19:58:18.300967 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com" 2025-10-02 19:58:18.300989 | controller | } 2025-10-02 19:58:18.607498 | controller | changed: 2025-10-02 19:58:18.607576 | controller | { 2025-10-02 19:58:18.607630 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com" 2025-10-02 19:58:18.607656 | controller | } 2025-10-02 19:58:18.932521 | controller | changed: 2025-10-02 19:58:18.932606 | controller | { 2025-10-02 19:58:18.932635 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com" 2025-10-02 19:58:18.932658 | controller | } 2025-10-02 19:58:19.234702 | controller | changed: 2025-10-02 19:58:19.234778 | controller | { 2025-10-02 19:58:19.234806 | 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-10-02 19:58:19.234828 | controller | } 2025-10-02 19:58:19.516205 | controller | changed: 2025-10-02 19:58:19.516284 | controller | { 2025-10-02 19:58:19.516520 | 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-10-02 19:58:19.516544 | controller | } 2025-10-02 19:58:19.815923 | controller | changed: 2025-10-02 19:58:19.816005 | controller | { 2025-10-02 19:58:19.816032 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner" 2025-10-02 19:58:19.816054 | controller | } 2025-10-02 19:58:20.142036 | controller | changed: 2025-10-02 19:58:20.142119 | controller | { 2025-10-02 19:58:20.142146 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com" 2025-10-02 19:58:20.142166 | controller | } 2025-10-02 19:58:20.469526 | controller | changed: 2025-10-02 19:58:20.469626 | controller | { 2025-10-02 19:58:20.469655 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com" 2025-10-02 19:58:20.469676 | controller | } 2025-10-02 19:58:20.778369 | controller | changed: 2025-10-02 19:58:20.778498 | controller | { 2025-10-02 19:58:20.778542 | controller | "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com" 2025-10-02 19:58:20.778574 | controller | } 2025-10-02 19:58:21.097519 | controller | changed: 2025-10-02 19:58:21.097610 | controller | { 2025-10-02 19:58:21.097638 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith" 2025-10-02 19:58:21.097659 | controller | } 2025-10-02 19:58:21.425322 | controller | changed: 2025-10-02 19:58:21.425431 | controller | { 2025-10-02 19:58:21.425461 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel" 2025-10-02 19:58:21.425483 | controller | } 2025-10-02 19:58:21.733104 | controller | changed: 2025-10-02 19:58:21.733189 | controller | { 2025-10-02 19:58:21.733216 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux" 2025-10-02 19:58:21.733236 | controller | } 2025-10-02 19:58:22.059563 | controller | changed: 2025-10-02 19:58:22.059657 | controller | { 2025-10-02 19:58:22.059686 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr" 2025-10-02 19:58:22.059706 | controller | } 2025-10-02 19:58:22.401457 | controller | changed: 2025-10-02 19:58:22.401652 | controller | { 2025-10-02 19:58:22.401691 | 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-10-02 19:58:22.401717 | controller | } 2025-10-02 19:58:22.719971 | controller | changed: 2025-10-02 19:58:22.720045 | controller | { 2025-10-02 19:58:22.720072 | 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-10-02 19:58:22.720100 | controller | } 2025-10-02 19:58:23.044307 | controller | changed: 2025-10-02 19:58:23.044400 | controller | { 2025-10-02 19:58:23.044433 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9" 2025-10-02 19:58:23.044454 | controller | } 2025-10-02 19:58:23.375179 | controller | changed: 2025-10-02 19:58:23.375266 | controller | { 2025-10-02 19:58:23.375295 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora" 2025-10-02 19:58:23.375317 | controller | } 2025-10-02 19:58:23.684181 | controller | changed: 2025-10-02 19:58:23.684267 | controller | { 2025-10-02 19:58:23.684294 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac" 2025-10-02 19:58:23.684314 | controller | } 2025-10-02 19:58:23.992148 | controller | changed: 2025-10-02 19:58:23.992233 | controller | { 2025-10-02 19:58:23.992260 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop" 2025-10-02 19:58:23.992281 | controller | } 2025-10-02 19:58:24.314754 | controller | changed: 2025-10-02 19:58:24.314842 | controller | { 2025-10-02 19:58:24.314869 | 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-10-02 19:58:24.314889 | controller | } 2025-10-02 19:58:24.633581 | controller | changed: 2025-10-02 19:58:24.633683 | controller | { 2025-10-02 19:58:24.633707 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com" 2025-10-02 19:58:24.633725 | controller | } 2025-10-02 19:58:24.953231 | controller | changed: 2025-10-02 19:58:24.953369 | controller | { 2025-10-02 19:58:24.953431 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com" 2025-10-02 19:58:24.953454 | controller | } 2025-10-02 19:58:25.278190 | controller | changed: 2025-10-02 19:58:25.282477 | controller | { 2025-10-02 19:58:25.282526 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono" 2025-10-02 19:58:25.282549 | controller | } 2025-10-02 19:58:25.308774 | 2025-10-02 19:58:25.308846 | TASK [Set timezone to UTC] 2025-10-02 19:58:25.856511 | controller | changed: executed `/bin/timedatectl set-timezone UTC` 2025-10-02 19:58:25.862215 | 2025-10-02 19:58:25.862281 | TASK [Create nodepool directory] 2025-10-02 19:58:26.170218 | controller | changed 2025-10-02 19:58:26.175885 | 2025-10-02 19:58:26.175954 | TASK [Create nodepool sub_nodes file] 2025-10-02 19:58:27.292507 | controller | changed 2025-10-02 19:58:27.297681 | 2025-10-02 19:58:27.297751 | TASK [Create nodepool sub_nodes_private file] 2025-10-02 19:58:28.400024 | controller | changed 2025-10-02 19:58:28.405080 | 2025-10-02 19:58:28.405161 | LOOP [Populate nodepool sub_nodes file] 2025-10-02 19:58:28.434211 | 2025-10-02 19:58:28.434368 | LOOP [Populate nodepool sub_nodes_private file] 2025-10-02 19:58:28.464060 | 2025-10-02 19:58:28.464224 | TASK [Create nodepool primary file] 2025-10-02 19:58:28.487764 | controller | skipping: Conditional result was False 2025-10-02 19:58:28.493280 | 2025-10-02 19:58:28.493358 | TASK [Create nodepool node_private for this node] 2025-10-02 19:58:29.542350 | controller | changed 2025-10-02 19:58:29.547921 | 2025-10-02 19:58:29.547988 | LOOP [Copy ssh keys to nodepool directory] 2025-10-02 19:58:29.978121 | controller | ok: Item: id_rsa Runtime: 0:00:00.005989 2025-10-02 19:58:29.978299 | 2025-10-02 19:58:30.232111 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006404 2025-10-02 19:58:30.238743 | 2025-10-02 19:58:30.238843 | TASK [Add sudoers role for zuul-sudo-grep.sh] 2025-10-02 19:58:31.404648 | controller | changed 2025-10-02 19:58:31.410631 | 2025-10-02 19:58:31.410713 | TASK [Validate sudoers config after edits] 2025-10-02 19:58:31.721513 | controller | /etc/sudoers: parsed OK 2025-10-02 19:58:31.721575 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK 2025-10-02 19:58:31.721584 | controller | /etc/sudoers.d/zuul: parsed OK 2025-10-02 19:58:31.721590 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK 2025-10-02 19:58:31.939248 | controller | ok: Runtime: 0:00:00.006170 2025-10-02 19:58:31.944695 | 2025-10-02 19:58:31.944763 | TASK [Show the environment passed in to job shell scripts] 2025-10-02 19:58:32.232466 | controller | SHELL=/bin/bash 2025-10-02 19:58:32.232514 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework 2025-10-02 19:58:32.232524 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework 2025-10-02 19:58:32.232531 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/62/3362/41f2edaa0ac45cd85919f70775e84cf472326a6e 2025-10-02 19:58:32.232537 | controller | PWD=/home/zuul 2025-10-02 19:58:32.232543 | controller | ZUUL_PIPELINE=github-check 2025-10-02 19:58:32.232548 | controller | LOGNAME=zuul 2025-10-02 19:58:32.232554 | controller | XDG_SESSION_TYPE=tty 2025-10-02 19:58:32.232559 | controller | _=/usr/bin/env 2025-10-02 19:58:32.232564 | controller | MOTD_SHOWN=pam 2025-10-02 19:58:32.232622 | controller | HOME=/home/zuul 2025-10-02 19:58:32.232630 | controller | LANG=en_US.UTF-8 2025-10-02 19:58:32.232635 | controller | SSH_CONNECTION=192.168.25.12 59476 192.168.25.229 22 2025-10-02 19:58:32.232641 | 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-10-02 19:58:32.232651 | controller | ZUUL_CHANGE_IDS=3362,41f2edaa0ac45cd85919f70775e84cf472326a6e 2025-10-02 19:58:32.232656 | controller | WORKSPACE=/home/zuul/workspace 2025-10-02 19:58:32.232662 | controller | XDG_SESSION_CLASS=user 2025-10-02 19:58:32.232668 | controller | SELINUX_ROLE_REQUESTED= 2025-10-02 19:58:32.232673 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s 2025-10-02 19:58:32.232678 | controller | USER=zuul 2025-10-02 19:58:32.232683 | controller | ZUUL_VOTING=True 2025-10-02 19:58:32.232689 | controller | BUILD_TIMEOUT=1800000 2025-10-02 19:58:32.232694 | controller | SELINUX_USE_CURRENT_RANGE= 2025-10-02 19:58:32.232699 | controller | SHLVL=1 2025-10-02 19:58:32.232705 | controller | ZUUL_PATCHSET=41f2edaa0ac45cd85919f70775e84cf472326a6e 2025-10-02 19:58:32.232710 | controller | XDG_SESSION_ID=1 2025-10-02 19:58:32.232715 | controller | ZUUL_BRANCH=main 2025-10-02 19:58:32.232720 | controller | XDG_RUNTIME_DIR=/run/user/1000 2025-10-02 19:58:32.232726 | controller | SSH_CLIENT=192.168.25.12 59476 22 2025-10-02 19:58:32.232731 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/ 2025-10-02 19:58:32.232736 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima: 2025-10-02 19:58:32.232742 | controller | which_declare=declare -f 2025-10-02 19:58:32.232748 | 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-10-02 19:58:32.232754 | controller | SELINUX_LEVEL_REQUESTED= 2025-10-02 19:58:32.232759 | controller | ZUUL_CHANGE=3362 2025-10-02 19:58:32.232764 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus 2025-10-02 19:58:32.232769 | controller | ZUUL_UUID=710274db8c2a411badea6a8fba077a23 2025-10-02 19:58:32.232776 | controller | BASH_FUNC_which%%=() { ( alias; 2025-10-02 19:58:32.232782 | controller | eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@ 2025-10-02 19:58:32.232788 | controller | } 2025-10-02 19:58:32.469489 | controller | ok: Runtime: 0:00:00.008165 2025-10-02 19:58:32.475338 | 2025-10-02 19:58:32.475421 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars] 2025-10-02 19:58:32.488761 | controller | skipping: Conditional result was False 2025-10-02 19:58:32.494306 | 2025-10-02 19:58:32.494375 | TASK [Symlink /home/zuul-worker/workspace] 2025-10-02 19:58:33.043876 | controller | skipping: Conditional result was False 2025-10-02 19:58:33.049817 | 2025-10-02 19:58:33.049883 | TASK [Ensure legacy workspace directory] 2025-10-02 19:58:33.344058 | controller | changed 2025-10-02 19:58:33.362935 | 2025-10-02 19:58:33.363004 | PLAY RECAP 2025-10-02 19:58:33.363058 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-02 19:58:33.363089 | 2025-10-02 19:58:33.442670 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master] 2025-10-02 19:58:33.443365 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main] 2025-10-02 19:58:33.990568 | 2025-10-02 19:58:33.990677 | PLAY [Run ci/playbooks/dump_zuul_data.yml] 2025-10-02 19:58:34.010858 | 2025-10-02 19:58:34.010928 | TASK [Create zuul-output directory] 2025-10-02 19:58:34.434410 | controller | changed 2025-10-02 19:58:34.440151 | 2025-10-02 19:58:34.440244 | TASK [Slurp Zuul inventory test] 2025-10-02 19:58:34.748538 | controller -> localhost | ok 2025-10-02 19:58:34.759982 | 2025-10-02 19:58:34.760065 | TASK [Save zuul inventory] 2025-10-02 19:58:36.070166 | controller | changed 2025-10-02 19:58:36.075937 | 2025-10-02 19:58:36.076016 | TASK [Save zuul vars without the change_message] 2025-10-02 19:58:37.216064 | controller | changed 2025-10-02 19:58:37.239602 | 2025-10-02 19:58:37.239671 | PLAY RECAP 2025-10-02 19:58:37.239778 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 19:58:37.239811 | 2025-10-02 19:58:37.316466 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main] 2025-10-02 19:58:37.323285 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main] 2025-10-02 19:58:37.968533 | 2025-10-02 19:58:37.968639 | PLAY [Run ci/playbooks/molecule-prepare.yml] 2025-10-02 19:58:37.988546 | 2025-10-02 19:58:37.988639 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh] 2025-10-02 19:58:38.016893 | controller | ok 2025-10-02 19:58:38.039825 | 2025-10-02 19:58:38.039911 | TASK [mirror-info-fork : Set mirror_fqdn if not defined] 2025-10-02 19:58:38.069825 | controller | skipping: Conditional result was False 2025-10-02 19:58:38.076001 | 2025-10-02 19:58:38.076095 | TASK [mirror-info-fork : Create /etc/ci] 2025-10-02 19:58:38.506114 | controller | ok 2025-10-02 19:58:38.512484 | 2025-10-02 19:58:38.512569 | TASK [mirror-info-fork : Install ci_mirror script] 2025-10-02 19:58:39.507345 | controller | ok 2025-10-02 19:58:39.517322 | 2025-10-02 19:58:39.517407 | TASK [Prepare workspace] 2025-10-02 19:58:39.535782 | controller | ok 2025-10-02 19:58:39.553512 | 2025-10-02 19:58:39.553584 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-02 19:58:39.937397 | controller | ok 2025-10-02 19:58:39.943849 | 2025-10-02 19:58:39.943918 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-02 19:58:42.205646 | controller | Output suppressed because no_log was given 2025-10-02 19:58:42.217153 | 2025-10-02 19:58:42.217235 | LOOP [Create zuul-output directory] 2025-10-02 19:58:42.507952 | controller | changed: "/home/zuul/ci-framework-data/logs" 2025-10-02 19:58:42.772895 | controller | ok: "/home/zuul/zuul-output/logs" 2025-10-02 19:58:42.789134 | 2025-10-02 19:58:42.789242 | TASK [Install required packages] 2025-10-02 19:58:59.265764 | controller | ok: Nothing to do 2025-10-02 19:58:59.270932 | 2025-10-02 19:58:59.270994 | TASK [Install venv] 2025-10-02 20:00:01.330144 | controller | changed 2025-10-02 20:00:01.358208 | 2025-10-02 20:00:01.358299 | PLAY RECAP 2025-10-02 20:00:01.358344 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-02 20:00:01.358369 | 2025-10-02 20:00:01.440689 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main] 2025-10-02 20:00:01.441475 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main] 2025-10-02 20:00:02.026780 | 2025-10-02 20:00:02.026885 | PLAY [Run ci/playbooks/molecule-test.yml] 2025-10-02 20:00:02.059922 | 2025-10-02 20:00:02.060013 | TASK [Gather required facts] 2025-10-02 20:00:02.724290 | controller | ok 2025-10-02 20:00:02.733356 | 2025-10-02 20:00:02.733452 | TASK [Load environment var if instructed to] 2025-10-02 20:00:02.762313 | controller | skipping: Conditional result was False 2025-10-02 20:00:02.768355 | 2025-10-02 20:00:02.768443 | TASK [Run molecule] 2025-10-02 20:00:03.907762 | controller | INFO Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml 2025-10-02 20:00:03.977611 | controller | INFO Performing prerun with role_name_check=0... 2025-10-02 20:00:21.496156 | 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-10-02 20:00:21.496581 | 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-10-02 20:00:21.497030 | 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-10-02 20:00:21.497482 | 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-10-02 20:00:21.497952 | controller | WARNING Another version of 'cifmw.general' 1.0.0+41f2edaa was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0+41f2edaa (/home/zuul/.ansible/collections/ansible_collections). 2025-10-02 20:00:21.498372 | 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-10-02 20:00:21.498810 | 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-10-02 20:00:21.499245 | 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-10-02 20:00:21.499680 | 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-10-02 20:00:21.500125 | 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-10-02 20:00:21.500555 | 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-10-02 20:00:21.501041 | 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-10-02 20:00:21.501585 | 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-10-02 20:00:21.501869 | 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-10-02 20:00:21.502303 | 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-10-02 20:00:21.511713 | controller | INFO Running default > prepare 2025-10-02 20:00:22.250783 | controller | 2025-10-02 20:00:22.250855 | controller | PLAY [Prepare] ***************************************************************** 2025-10-02 20:00:22.250963 | controller | 2025-10-02 20:00:22.251059 | controller | TASK [Gathering Facts] ********************************************************* 2025-10-02 20:00:22.251162 | controller | Thursday 02 October 2025 20:00:22 +0000 (0:00:00.013) 0:00:00.013 ****** 2025-10-02 20:00:23.134340 | controller | ok: [instance] 2025-10-02 20:00:23.134440 | controller | 2025-10-02 20:00:23.134559 | controller | TASK [test_deps : Gather facts if they don't exist] **************************** 2025-10-02 20:00:23.134681 | controller | Thursday 02 October 2025 20:00:23 +0000 (0:00:00.884) 0:00:00.897 ****** 2025-10-02 20:00:23.154001 | controller | skipping: [instance] 2025-10-02 20:00:23.154085 | controller | 2025-10-02 20:00:23.154187 | controller | TASK [test_deps : Gather variables for each operating system] ****************** 2025-10-02 20:00:23.154288 | controller | Thursday 02 October 2025 20:00:23 +0000 (0:00:00.019) 0:00:00.917 ****** 2025-10-02 20:00:23.202228 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml) 2025-10-02 20:00:23.202273 | controller | 2025-10-02 20:00:23.202446 | controller | TASK [test_deps : Detect mirrors file] ***************************************** 2025-10-02 20:00:23.202531 | controller | Thursday 02 October 2025 20:00:23 +0000 (0:00:00.048) 0:00:00.965 ****** 2025-10-02 20:00:23.492510 | controller | ok: [instance] 2025-10-02 20:00:23.492563 | controller | 2025-10-02 20:00:23.492718 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] *********** 2025-10-02 20:00:23.492803 | controller | Thursday 02 October 2025 20:00:23 +0000 (0:00:00.290) 0:00:01.255 ****** 2025-10-02 20:00:23.815020 | controller | ok: [instance] 2025-10-02 20:00:23.815089 | controller | 2025-10-02 20:00:23.815194 | controller | TASK [test_deps : Disable ubi 9 repos] ***************************************** 2025-10-02 20:00:23.815294 | controller | Thursday 02 October 2025 20:00:23 +0000 (0:00:00.322) 0:00:01.578 ****** 2025-10-02 20:00:24.569493 | controller | ok: [instance] => (item=ubi-9-appstream) 2025-10-02 20:00:24.569620 | controller | ok: [instance] => (item=ubi-9-baseos) 2025-10-02 20:00:24.569736 | controller | ok: [instance] => (item=ubi-9-codeready-builder) 2025-10-02 20:00:24.569839 | controller | 2025-10-02 20:00:24.569961 | controller | TASK [Deploy repo-setup] ******************************************************* 2025-10-02 20:00:24.570058 | controller | Thursday 02 October 2025 20:00:24 +0000 (0:00:00.754) 0:00:02.332 ****** 2025-10-02 20:00:24.631774 | controller | 2025-10-02 20:00:24.631854 | controller | TASK [repo_setup : Ensure directories are present] ***************************** 2025-10-02 20:00:24.631982 | controller | Thursday 02 October 2025 20:00:24 +0000 (0:00:00.062) 0:00:02.395 ****** 2025-10-02 20:00:25.249393 | controller | changed: [instance] => (item=tmp) 2025-10-02 20:00:25.249501 | controller | changed: [instance] => (item=artifacts/repositories) 2025-10-02 20:00:25.249645 | controller | changed: [instance] => (item=venv/repo_setup) 2025-10-02 20:00:25.249734 | controller | 2025-10-02 20:00:25.249862 | controller | TASK [repo_setup : Make sure git-core package is installed] ******************** 2025-10-02 20:00:25.249995 | controller | Thursday 02 October 2025 20:00:25 +0000 (0:00:00.616) 0:00:03.012 ****** 2025-10-02 20:00:26.134613 | controller | ok: [instance] 2025-10-02 20:00:27.417138 | controller | 2025-10-02 20:00:27.417179 | controller | TASK [repo_setup : Get repo-setup repository] ********************************** 2025-10-02 20:00:27.417193 | controller | Thursday 02 October 2025 20:00:26 +0000 (0:00:00.884) 0:00:03.897 ****** 2025-10-02 20:00:27.417205 | controller | changed: [instance] 2025-10-02 20:00:35.866476 | controller | 2025-10-02 20:00:35.866551 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************ 2025-10-02 20:00:35.866560 | controller | Thursday 02 October 2025 20:00:27 +0000 (0:00:01.282) 0:00:05.179 ****** 2025-10-02 20:00:35.866573 | controller | changed: [instance] 2025-10-02 20:00:36.689644 | controller | 2025-10-02 20:00:36.689754 | controller | TASK [repo_setup : Install repo-setup package] ********************************* 2025-10-02 20:00:36.689765 | controller | Thursday 02 October 2025 20:00:35 +0000 (0:00:08.449) 0:00:13.628 ****** 2025-10-02 20:00:36.689785 | controller | changed: [instance] 2025-10-02 20:00:36.720035 | controller | 2025-10-02 20:00:36.720100 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] *** 2025-10-02 20:00:36.720109 | controller | Thursday 02 October 2025 20:00:36 +0000 (0:00:00.822) 0:00:14.452 ****** 2025-10-02 20:00:36.720122 | controller | skipping: [instance] 2025-10-02 20:00:37.615436 | controller | 2025-10-02 20:00:37.615478 | controller | TASK [repo_setup : Run repo-setup] ********************************************* 2025-10-02 20:00:37.615487 | controller | Thursday 02 October 2025 20:00:36 +0000 (0:00:00.030) 0:00:14.482 ****** 2025-10-02 20:00:37.615498 | controller | changed: [instance] 2025-10-02 20:00:37.615705 | controller | 2025-10-02 20:00:37.615719 | controller | TASK [repo_setup : Get component repo] ***************************************** 2025-10-02 20:00:37.659751 | controller | Thursday 02 October 2025 20:00:37 +0000 (0:00:00.895) 0:00:15.378 ****** 2025-10-02 20:00:37.659772 | controller | skipping: [instance] 2025-10-02 20:00:37.706463 | controller | 2025-10-02 20:00:37.706554 | controller | TASK [repo_setup : Rename component repo] ************************************** 2025-10-02 20:00:37.706566 | controller | Thursday 02 October 2025 20:00:37 +0000 (0:00:00.044) 0:00:15.423 ****** 2025-10-02 20:00:37.706587 | controller | skipping: [instance] 2025-10-02 20:00:37.755265 | controller | 2025-10-02 20:00:37.755301 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] ******* 2025-10-02 20:00:37.755311 | controller | Thursday 02 October 2025 20:00:37 +0000 (0:00:00.046) 0:00:15.469 ****** 2025-10-02 20:00:37.755346 | controller | skipping: [instance] 2025-10-02 20:00:38.350382 | controller | 2025-10-02 20:00:38.350420 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************ 2025-10-02 20:00:38.350428 | controller | Thursday 02 October 2025 20:00:37 +0000 (0:00:00.049) 0:00:15.518 ****** 2025-10-02 20:00:38.350439 | controller | changed: [instance] 2025-10-02 20:00:38.857050 | controller | 2025-10-02 20:00:38.857095 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] ******************* 2025-10-02 20:00:38.857103 | controller | Thursday 02 October 2025 20:00:38 +0000 (0:00:00.595) 0:00:16.113 ****** 2025-10-02 20:00:38.857115 | controller | changed: [instance] 2025-10-02 20:00:38.896775 | controller | 2025-10-02 20:00:38.896802 | controller | TASK [repo_setup : Dump current-podified hash] ********************************* 2025-10-02 20:00:38.896811 | controller | Thursday 02 October 2025 20:00:38 +0000 (0:00:00.506) 0:00:16.619 ****** 2025-10-02 20:00:38.896822 | controller | skipping: [instance] 2025-10-02 20:00:38.933169 | controller | 2025-10-02 20:00:38.933187 | controller | TASK [repo_setup : Slurp current podified hash] ******************************** 2025-10-02 20:00:38.933195 | controller | Thursday 02 October 2025 20:00:38 +0000 (0:00:00.039) 0:00:16.659 ****** 2025-10-02 20:00:38.933204 | controller | skipping: [instance] 2025-10-02 20:00:38.969798 | controller | 2025-10-02 20:00:38.969820 | controller | TASK [repo_setup : Update the value of full_hash] ****************************** 2025-10-02 20:00:38.969830 | controller | Thursday 02 October 2025 20:00:38 +0000 (0:00:00.036) 0:00:16.696 ****** 2025-10-02 20:00:38.969841 | controller | skipping: [instance] 2025-10-02 20:00:39.015271 | controller | 2025-10-02 20:00:39.015289 | controller | TASK [repo_setup : Export hashes facts for further use] ************************ 2025-10-02 20:00:39.015297 | controller | Thursday 02 October 2025 20:00:38 +0000 (0:00:00.036) 0:00:16.733 ****** 2025-10-02 20:00:39.015306 | controller | ok: [instance] 2025-10-02 20:00:39.050581 | controller | 2025-10-02 20:00:39.050600 | controller | TASK [repo_setup : Create download directory] ********************************** 2025-10-02 20:00:39.050607 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.045) 0:00:16.778 ****** 2025-10-02 20:00:39.050616 | controller | skipping: [instance] 2025-10-02 20:00:39.050758 | controller | 2025-10-02 20:00:39.050901 | controller | TASK [repo_setup : Print the URL to request] *********************************** 2025-10-02 20:00:39.051051 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.035) 0:00:16.814 ****** 2025-10-02 20:00:39.088897 | controller | skipping: [instance] 2025-10-02 20:00:39.089103 | controller | 2025-10-02 20:00:39.089262 | controller | TASK [Download the RPM] ******************************************************** 2025-10-02 20:00:39.089425 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.038) 0:00:16.852 ****** 2025-10-02 20:00:39.127632 | controller | skipping: [instance] 2025-10-02 20:00:39.127816 | controller | 2025-10-02 20:00:39.127991 | controller | TASK [repo_setup : Install RHOS Release tool] ********************************** 2025-10-02 20:00:39.128175 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.038) 0:00:16.891 ****** 2025-10-02 20:00:39.164967 | controller | skipping: [instance] 2025-10-02 20:00:39.165171 | controller | 2025-10-02 20:00:39.165366 | controller | TASK [repo_setup : Get rhos-release tool version] ****************************** 2025-10-02 20:00:39.165512 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.037) 0:00:16.928 ****** 2025-10-02 20:00:39.200122 | controller | skipping: [instance] 2025-10-02 20:00:39.200307 | controller | 2025-10-02 20:00:39.200505 | controller | TASK [repo_setup : Print rhos-release tool version] **************************** 2025-10-02 20:00:39.200645 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.035) 0:00:16.963 ****** 2025-10-02 20:00:39.242299 | controller | skipping: [instance] 2025-10-02 20:00:39.242515 | controller | 2025-10-02 20:00:39.242670 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] *** 2025-10-02 20:00:39.242810 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.042) 0:00:17.005 ****** 2025-10-02 20:00:39.275695 | controller | skipping: [instance] 2025-10-02 20:00:39.275891 | controller | 2025-10-02 20:00:39.276087 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] *************************** 2025-10-02 20:00:39.276254 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.033) 0:00:17.039 ****** 2025-10-02 20:00:39.496902 | controller | ok: [instance] 2025-10-02 20:00:39.769511 | controller | 2025-10-02 20:00:39.769563 | controller | TASK [repo_setup : Use RDO proxy mirrors] ************************************** 2025-10-02 20:00:39.769572 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.220) 0:00:17.259 ****** 2025-10-02 20:00:39.769585 | controller | changed: [instance] 2025-10-02 20:00:40.043119 | controller | 2025-10-02 20:00:40.043159 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] *** 2025-10-02 20:00:40.043168 | controller | Thursday 02 October 2025 20:00:39 +0000 (0:00:00.272) 0:00:17.532 ****** 2025-10-02 20:00:40.043179 | controller | changed: [instance] 2025-10-02 20:00:40.072140 | controller | 2025-10-02 20:00:40.072161 | controller | TASK [repo_setup : Check for gating.repo file on content provider] ************* 2025-10-02 20:00:40.072169 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.273) 0:00:17.806 ****** 2025-10-02 20:00:40.072177 | controller | skipping: [instance] 2025-10-02 20:00:40.101647 | controller | 2025-10-02 20:00:40.101730 | controller | TASK [repo_setup : Populate gating repo from content provider ip] ************** 2025-10-02 20:00:40.101742 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.029) 0:00:17.835 ****** 2025-10-02 20:00:40.101763 | controller | skipping: [instance] 2025-10-02 20:00:40.131464 | controller | 2025-10-02 20:00:40.131503 | controller | TASK [repo_setup : Check for DLRN repo at the destination] ********************* 2025-10-02 20:00:40.131511 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.029) 0:00:17.865 ****** 2025-10-02 20:00:40.131522 | controller | skipping: [instance] 2025-10-02 20:00:40.161457 | controller | 2025-10-02 20:00:40.161514 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] *** 2025-10-02 20:00:40.161523 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.029) 0:00:17.894 ****** 2025-10-02 20:00:40.161552 | controller | skipping: [instance] 2025-10-02 20:00:40.190451 | controller | 2025-10-02 20:00:40.190490 | controller | TASK [repo_setup : Check for DLRN component repo] ****************************** 2025-10-02 20:00:40.190502 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.029) 0:00:17.924 ****** 2025-10-02 20:00:40.190516 | controller | skipping: [instance] 2025-10-02 20:00:40.218273 | controller | 2025-10-02 20:00:40.218313 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] *** 2025-10-02 20:00:40.218391 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.028) 0:00:17.953 ****** 2025-10-02 20:00:40.218405 | controller | skipping: [instance] 2025-10-02 20:00:40.218522 | controller | 2025-10-02 20:00:40.218538 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ******** 2025-10-02 20:00:40.218646 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.028) 0:00:17.981 ****** 2025-10-02 20:00:40.239078 | controller | skipping: [instance] 2025-10-02 20:00:40.239206 | controller | 2025-10-02 20:00:40.239394 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ****** 2025-10-02 20:00:40.239555 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.020) 0:00:18.002 ****** 2025-10-02 20:00:40.276090 | controller | skipping: [instance] 2025-10-02 20:00:40.276212 | controller | 2025-10-02 20:00:40.276412 | controller | TASK [repo_setup : Cleanup existing metadata] ********************************** 2025-10-02 20:00:40.276550 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.036) 0:00:18.039 ****** 2025-10-02 20:00:40.296772 | controller | skipping: [instance] 2025-10-02 20:00:40.296899 | controller | 2025-10-02 20:00:40.296915 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] ********* 2025-10-02 20:00:40.297037 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.020) 0:00:18.060 ****** 2025-10-02 20:00:40.320404 | controller | skipping: [instance] 2025-10-02 20:00:40.320457 | controller | 2025-10-02 20:00:40.320634 | controller | TASK [test_deps : Look for redhat-release rpm] ********************************* 2025-10-02 20:00:40.320745 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.023) 0:00:18.084 ****** 2025-10-02 20:00:40.354038 | controller | skipping: [instance] 2025-10-02 20:00:40.354113 | controller | 2025-10-02 20:00:40.354288 | controller | TASK [test_deps : Remove redhat-release] *************************************** 2025-10-02 20:00:40.354435 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.033) 0:00:18.117 ****** 2025-10-02 20:00:40.392103 | controller | skipping: [instance] 2025-10-02 20:00:40.392242 | controller | 2025-10-02 20:00:40.392459 | controller | TASK [test_deps : Install centos-stream-release] ******************************* 2025-10-02 20:00:40.392588 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.038) 0:00:18.155 ****** 2025-10-02 20:00:40.427282 | controller | skipping: [instance] 2025-10-02 20:00:40.427422 | controller | 2025-10-02 20:00:40.427637 | controller | TASK [test_deps : Install additional packages] ********************************* 2025-10-02 20:00:40.427748 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.035) 0:00:18.190 ****** 2025-10-02 20:00:40.464776 | controller | skipping: [instance] 2025-10-02 20:00:40.464894 | controller | 2025-10-02 20:00:40.465015 | controller | TASK [test_deps : Install selinux python libs] ********************************* 2025-10-02 20:00:40.465157 | controller | Thursday 02 October 2025 20:00:40 +0000 (0:00:00.037) 0:00:18.228 ****** 2025-10-02 20:01:32.447791 | controller | ok: [instance] 2025-10-02 20:01:33.711704 | controller | 2025-10-02 20:01:33.711740 | controller | TASK [test_deps : Install python yaml libs] ************************************ 2025-10-02 20:01:33.711749 | controller | Thursday 02 October 2025 20:01:32 +0000 (0:00:51.981) 0:01:10.210 ****** 2025-10-02 20:01:33.711759 | controller | ok: [instance] 2025-10-02 20:01:33.746580 | controller | 2025-10-02 20:01:33.746662 | controller | TASK [test_deps : Install extra packages] ************************************** 2025-10-02 20:01:33.746673 | controller | Thursday 02 October 2025 20:01:33 +0000 (0:00:01.264) 0:01:11.474 ****** 2025-10-02 20:01:33.746693 | controller | skipping: [instance] 2025-10-02 20:01:33.746733 | controller | 2025-10-02 20:01:33.746743 | controller | TASK [Ensure CRC is started] *************************************************** 2025-10-02 20:04:17.174564 | controller | Thursday 02 October 2025 20:01:33 +0000 (0:00:00.035) 0:01:11.510 ****** 2025-10-02 20:04:17.174618 | controller | changed: [instance] 2025-10-02 20:04:17.508609 | controller | 2025-10-02 20:04:17.508646 | controller | TASK [Inject crc hostname/IP in hosts] ***************************************** 2025-10-02 20:04:17.508654 | controller | Thursday 02 October 2025 20:04:17 +0000 (0:02:43.427) 0:03:54.937 ****** 2025-10-02 20:04:17.508664 | controller | changed: [instance] 2025-10-02 20:04:17.508908 | controller | 2025-10-02 20:04:17.509052 | controller | PLAY RECAP ********************************************************************* 2025-10-02 20:04:17.509063 | controller | instance : ok=21 changed=11 unreachable=0 failed=0 skipped=30 rescued=0 ignored=0 2025-10-02 20:04:17.509071 | controller | 2025-10-02 20:04:17.509271 | controller | Thursday 02 October 2025 20:04:17 +0000 (0:00:00.334) 0:03:55.272 ****** 2025-10-02 20:04:17.509283 | controller | =============================================================================== 2025-10-02 20:04:17.509416 | controller | Ensure CRC is started ------------------------------------------------- 163.43s 2025-10-02 20:04:17.509447 | controller | test_deps : Install selinux python libs -------------------------------- 51.98s 2025-10-02 20:04:17.509528 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.45s 2025-10-02 20:04:17.509609 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.28s 2025-10-02 20:04:17.509953 | controller | test_deps : Install python yaml libs ------------------------------------ 1.26s 2025-10-02 20:04:17.510594 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.90s 2025-10-02 20:04:17.510632 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.88s 2025-10-02 20:04:17.510646 | controller | Gathering Facts --------------------------------------------------------- 0.88s 2025-10-02 20:04:17.510718 | controller | repo_setup : Install repo-setup package --------------------------------- 0.82s 2025-10-02 20:04:17.510729 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.75s 2025-10-02 20:04:17.510736 | controller | repo_setup : Ensure directories are present ----------------------------- 0.62s 2025-10-02 20:04:17.510741 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.60s 2025-10-02 20:04:17.510746 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.51s 2025-10-02 20:04:17.510751 | controller | Inject crc hostname/IP in hosts ----------------------------------------- 0.33s 2025-10-02 20:04:17.510759 | controller | test_deps : Disable ubi host subscription-manager integration ----------- 0.32s 2025-10-02 20:04:17.511111 | controller | test_deps : Detect mirrors file ----------------------------------------- 0.29s 2025-10-02 20:04:17.511122 | controller | repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist) --- 0.27s 2025-10-02 20:04:17.570820 | controller | repo_setup : Use RDO proxy mirrors -------------------------------------- 0.27s 2025-10-02 20:04:17.570854 | controller | repo_setup : Check for /etc/ci/mirror_info.sh --------------------------- 0.22s 2025-10-02 20:04:17.570862 | controller | Deploy repo-setup ------------------------------------------------------- 0.06s 2025-10-02 20:04:17.570874 | controller | INFO Running default > converge 2025-10-02 20:04:18.035668 | controller | 2025-10-02 20:04:18.901484 | controller | PLAY [Converge] **************************************************************** 2025-10-02 20:04:18.901527 | controller | 2025-10-02 20:04:18.901535 | controller | TASK [Gathering Facts] ********************************************************* 2025-10-02 20:04:18.901541 | controller | Thursday 02 October 2025 20:04:18 +0000 (0:00:00.016) 0:00:00.016 ****** 2025-10-02 20:04:18.901553 | controller | ok: [instance] 2025-10-02 20:04:18.901662 | controller | 2025-10-02 20:04:18.901674 | controller | TASK [Load networking_definition] ********************************************** 2025-10-02 20:04:18.901756 | controller | Thursday 02 October 2025 20:04:18 +0000 (0:00:00.866) 0:00:00.882 ****** 2025-10-02 20:04:18.921562 | controller | ok: [instance] 2025-10-02 20:04:18.921678 | controller | 2025-10-02 20:04:18.921808 | controller | TASK [Check if new ssh keypair exists] ***************************************** 2025-10-02 20:04:18.921928 | controller | Thursday 02 October 2025 20:04:18 +0000 (0:00:00.020) 0:00:00.902 ****** 2025-10-02 20:04:18.945468 | controller | 2025-10-02 20:04:18.945585 | controller | TASK [recognize_ssh_keypair : Check if id_ed25519 key exists] ****************** 2025-10-02 20:04:18.945694 | controller | Thursday 02 October 2025 20:04:18 +0000 (0:00:00.023) 0:00:00.926 ****** 2025-10-02 20:04:19.235696 | controller | ok: [instance] 2025-10-02 20:04:19.235761 | controller | 2025-10-02 20:04:19.235876 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair exists] ****************** 2025-10-02 20:04:19.235980 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.290) 0:00:01.216 ****** 2025-10-02 20:04:19.255699 | controller | ok: [instance] 2025-10-02 20:04:19.255796 | controller | 2025-10-02 20:04:19.255895 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair does not exists] ********* 2025-10-02 20:04:19.256003 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.020) 0:00:01.237 ****** 2025-10-02 20:04:19.277664 | controller | skipping: [instance] 2025-10-02 20:04:19.277756 | controller | 2025-10-02 20:04:19.277857 | controller | TASK [Add the crc host dynamically] ******************************************** 2025-10-02 20:04:19.277968 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.021) 0:00:01.259 ****** 2025-10-02 20:04:19.299153 | controller | changed: [instance] 2025-10-02 20:04:19.299250 | controller | 2025-10-02 20:04:19.299403 | controller | TASK [Add ansible_host entry to "controller-0"] ******************************** 2025-10-02 20:04:19.299498 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.021) 0:00:01.280 ****** 2025-10-02 20:04:19.325235 | controller | changed: [instance] 2025-10-02 20:04:19.325339 | controller | 2025-10-02 20:04:19.325443 | controller | TASK [Add host key to controller-0] ******************************************** 2025-10-02 20:04:19.325554 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.025) 0:00:01.306 ****** 2025-10-02 20:04:19.656237 | controller | changed: [instance] 2025-10-02 20:04:19.656291 | controller | 2025-10-02 20:04:19.656439 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************ 2025-10-02 20:04:19.656530 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.330) 0:00:01.637 ****** 2025-10-02 20:04:19.956309 | controller | ok: [instance] 2025-10-02 20:04:19.956378 | controller | 2025-10-02 20:04:19.956510 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] ************* 2025-10-02 20:04:19.956625 | controller | Thursday 02 October 2025 20:04:19 +0000 (0:00:00.300) 0:00:01.937 ****** 2025-10-02 20:04:20.140244 | controller | changed: [instance] 2025-10-02 20:04:20.140293 | controller | 2025-10-02 20:04:20.140475 | controller | TASK [libvirt_manager : Check if KVM is enabled] ******************************* 2025-10-02 20:04:20.140593 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.183) 0:00:02.121 ****** 2025-10-02 20:04:20.323266 | controller | ok: [instance] 2025-10-02 20:04:20.323332 | controller | 2025-10-02 20:04:20.323491 | controller | TASK [libvirt_manager : Fail if KVM not enabled] ******************************* 2025-10-02 20:04:20.323589 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.182) 0:00:02.304 ****** 2025-10-02 20:04:20.351377 | controller | skipping: [instance] 2025-10-02 20:04:20.351508 | controller | 2025-10-02 20:04:20.351650 | controller | TASK [libvirt_manager : Check if VMX virtualization] *************************** 2025-10-02 20:04:20.351774 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.028) 0:00:02.332 ****** 2025-10-02 20:04:20.368636 | controller | skipping: [instance] 2025-10-02 20:04:20.368748 | controller | 2025-10-02 20:04:20.368876 | controller | TASK [libvirt_manager : Check if SVM virtualization] *************************** 2025-10-02 20:04:20.368975 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.017) 0:00:02.350 ****** 2025-10-02 20:04:20.388538 | controller | ok: [instance] 2025-10-02 20:04:20.388636 | controller | 2025-10-02 20:04:20.388744 | controller | TASK [libvirt_manager : Enable VMX virtualization] ***************************** 2025-10-02 20:04:20.388864 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.019) 0:00:02.369 ****** 2025-10-02 20:04:20.417948 | controller | skipping: [instance] 2025-10-02 20:04:20.417997 | controller | 2025-10-02 20:04:20.418138 | controller | TASK [libvirt_manager : Install packages required for using KVM] *************** 2025-10-02 20:04:20.418255 | controller | Thursday 02 October 2025 20:04:20 +0000 (0:00:00.029) 0:00:02.399 ****** 2025-10-02 20:04:31.454576 | controller | changed: [instance] 2025-10-02 20:04:31.454607 | controller | 2025-10-02 20:04:31.454615 | controller | TASK [libvirt_manager : Create rules.d polkit folder] ************************** 2025-10-02 20:04:31.454623 | controller | Thursday 02 October 2025 20:04:31 +0000 (0:00:11.036) 0:00:13.435 ****** 2025-10-02 20:04:31.670427 | controller | changed: [instance] 2025-10-02 20:04:31.670471 | controller | 2025-10-02 20:04:31.670591 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] ********************* 2025-10-02 20:04:31.670692 | controller | Thursday 02 October 2025 20:04:31 +0000 (0:00:00.215) 0:00:13.651 ****** 2025-10-02 20:04:32.157029 | controller | changed: [instance] 2025-10-02 20:04:32.157065 | controller | 2025-10-02 20:04:32.157159 | controller | TASK [libvirt_manager : Restart service polkit service] ************************ 2025-10-02 20:04:32.157287 | controller | Thursday 02 October 2025 20:04:32 +0000 (0:00:00.486) 0:00:14.138 ****** 2025-10-02 20:04:32.744056 | controller | changed: [instance] 2025-10-02 20:04:32.744404 | controller | 2025-10-02 20:04:32.941532 | controller | TASK [libvirt_manager : Remove directory for service override] ***************** 2025-10-02 20:04:32.941570 | controller | Thursday 02 October 2025 20:04:32 +0000 (0:00:00.587) 0:00:14.725 ****** 2025-10-02 20:04:32.941584 | controller | ok: [instance] 2025-10-02 20:04:32.942336 | controller | 2025-10-02 20:04:32.942358 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] *** 2025-10-02 20:04:32.942370 | controller | Thursday 02 October 2025 20:04:32 +0000 (0:00:00.197) 0:00:14.922 ****** 2025-10-02 20:04:33.608842 | controller | ok: [instance] 2025-10-02 20:04:33.608894 | controller | 2025-10-02 20:04:33.608976 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************ 2025-10-02 20:04:33.609079 | controller | Thursday 02 October 2025 20:04:33 +0000 (0:00:00.667) 0:00:15.589 ****** 2025-10-02 20:04:34.579578 | controller | changed: [instance] 2025-10-02 20:04:34.579637 | controller | 2025-10-02 20:04:34.579787 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] **** 2025-10-02 20:04:34.579894 | controller | Thursday 02 October 2025 20:04:34 +0000 (0:00:00.970) 0:00:16.560 ****** 2025-10-02 20:04:34.662568 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu) 2025-10-02 20:04:34.662620 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface) 2025-10-02 20:04:34.662629 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network) 2025-10-02 20:04:34.662637 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev) 2025-10-02 20:04:34.662762 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter) 2025-10-02 20:04:34.662864 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret) 2025-10-02 20:04:34.662971 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage) 2025-10-02 20:04:34.663079 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy) 2025-10-02 20:04:34.663182 | controller | 2025-10-02 20:04:34.663294 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] ********* 2025-10-02 20:04:34.663769 | controller | Thursday 02 October 2025 20:04:34 +0000 (0:00:00.082) 0:00:16.643 ****** 2025-10-02 20:04:34.998189 | controller | ok: [instance] 2025-10-02 20:04:35.338850 | controller | 2025-10-02 20:04:35.338886 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] ********** 2025-10-02 20:04:35.338899 | controller | Thursday 02 October 2025 20:04:34 +0000 (0:00:00.335) 0:00:16.979 ****** 2025-10-02 20:04:35.338910 | controller | ok: [instance] 2025-10-02 20:04:35.690095 | controller | 2025-10-02 20:04:35.690129 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] ************** 2025-10-02 20:04:35.690138 | controller | Thursday 02 October 2025 20:04:35 +0000 (0:00:00.340) 0:00:17.319 ****** 2025-10-02 20:04:35.690148 | controller | ok: [instance] 2025-10-02 20:04:36.048620 | controller | 2025-10-02 20:04:36.048651 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] **** 2025-10-02 20:04:36.048666 | controller | Thursday 02 October 2025 20:04:35 +0000 (0:00:00.351) 0:00:17.670 ****** 2025-10-02 20:04:36.048686 | controller | ok: [instance] 2025-10-02 20:04:36.048703 | controller | 2025-10-02 20:04:36.048710 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] ***** 2025-10-02 20:04:36.048808 | controller | Thursday 02 October 2025 20:04:36 +0000 (0:00:00.356) 0:00:18.027 ****** 2025-10-02 20:04:36.410561 | controller | ok: [instance] 2025-10-02 20:04:36.732128 | controller | 2025-10-02 20:04:36.732163 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] ********* 2025-10-02 20:04:36.732171 | controller | Thursday 02 October 2025 20:04:36 +0000 (0:00:00.364) 0:00:18.391 ****** 2025-10-02 20:04:36.732181 | controller | ok: [instance] 2025-10-02 20:04:37.054548 | controller | 2025-10-02 20:04:37.054582 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ****** 2025-10-02 20:04:37.054590 | controller | Thursday 02 October 2025 20:04:36 +0000 (0:00:00.321) 0:00:18.713 ****** 2025-10-02 20:04:37.054601 | controller | ok: [instance] 2025-10-02 20:04:37.054684 | controller | 2025-10-02 20:04:37.054714 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] ******* 2025-10-02 20:04:37.054727 | controller | Thursday 02 October 2025 20:04:37 +0000 (0:00:00.322) 0:00:19.035 ****** 2025-10-02 20:04:37.382546 | controller | ok: [instance] 2025-10-02 20:04:37.382628 | controller | 2025-10-02 20:04:37.382658 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] *********** 2025-10-02 20:04:37.382670 | controller | Thursday 02 October 2025 20:04:37 +0000 (0:00:00.328) 0:00:19.363 ****** 2025-10-02 20:04:37.703612 | controller | ok: [instance] 2025-10-02 20:04:37.703769 | controller | 2025-10-02 20:04:37.703906 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ****** 2025-10-02 20:04:37.703942 | controller | Thursday 02 October 2025 20:04:37 +0000 (0:00:00.321) 0:00:19.684 ****** 2025-10-02 20:04:38.033769 | controller | ok: [instance] 2025-10-02 20:04:38.033995 | controller | 2025-10-02 20:04:38.034028 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] ******* 2025-10-02 20:04:38.357349 | controller | Thursday 02 October 2025 20:04:38 +0000 (0:00:00.330) 0:00:20.015 ****** 2025-10-02 20:04:38.357399 | controller | ok: [instance] 2025-10-02 20:04:38.357434 | controller | 2025-10-02 20:04:38.357662 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] *********** 2025-10-02 20:04:38.682478 | controller | Thursday 02 October 2025 20:04:38 +0000 (0:00:00.323) 0:00:20.338 ****** 2025-10-02 20:04:38.682517 | controller | ok: [instance] 2025-10-02 20:04:38.682545 | controller | 2025-10-02 20:04:38.682687 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] ***** 2025-10-02 20:04:38.682800 | controller | Thursday 02 October 2025 20:04:38 +0000 (0:00:00.325) 0:00:20.663 ****** 2025-10-02 20:04:39.017131 | controller | ok: [instance] 2025-10-02 20:04:39.017180 | controller | 2025-10-02 20:04:39.017188 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ****** 2025-10-02 20:04:39.017197 | controller | Thursday 02 October 2025 20:04:39 +0000 (0:00:00.334) 0:00:20.998 ****** 2025-10-02 20:04:39.352676 | controller | ok: [instance] 2025-10-02 20:04:39.352727 | controller | 2025-10-02 20:04:39.352845 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] ********** 2025-10-02 20:04:39.352955 | controller | Thursday 02 October 2025 20:04:39 +0000 (0:00:00.335) 0:00:21.333 ****** 2025-10-02 20:04:39.687179 | controller | ok: [instance] 2025-10-02 20:04:39.687247 | controller | 2025-10-02 20:04:39.687395 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] ******* 2025-10-02 20:04:39.687500 | controller | Thursday 02 October 2025 20:04:39 +0000 (0:00:00.334) 0:00:21.668 ****** 2025-10-02 20:04:40.026032 | controller | ok: [instance] 2025-10-02 20:04:40.026087 | controller | 2025-10-02 20:04:40.026183 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ******** 2025-10-02 20:04:40.026302 | controller | Thursday 02 October 2025 20:04:40 +0000 (0:00:00.338) 0:00:22.007 ****** 2025-10-02 20:04:40.374582 | controller | ok: [instance] 2025-10-02 20:04:40.374641 | controller | 2025-10-02 20:04:40.374767 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************ 2025-10-02 20:04:40.374865 | controller | Thursday 02 October 2025 20:04:40 +0000 (0:00:00.348) 0:00:22.355 ****** 2025-10-02 20:04:40.696391 | controller | ok: [instance] 2025-10-02 20:04:40.696455 | controller | 2025-10-02 20:04:40.696569 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ****** 2025-10-02 20:04:40.696669 | controller | Thursday 02 October 2025 20:04:40 +0000 (0:00:00.321) 0:00:22.677 ****** 2025-10-02 20:04:41.043589 | controller | ok: [instance] 2025-10-02 20:04:41.043646 | controller | 2025-10-02 20:04:41.043754 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] ******* 2025-10-02 20:04:41.043856 | controller | Thursday 02 October 2025 20:04:41 +0000 (0:00:00.347) 0:00:23.024 ****** 2025-10-02 20:04:41.374124 | controller | ok: [instance] 2025-10-02 20:04:41.374222 | controller | 2025-10-02 20:04:41.374387 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] *********** 2025-10-02 20:04:41.374524 | controller | Thursday 02 October 2025 20:04:41 +0000 (0:00:00.330) 0:00:23.355 ****** 2025-10-02 20:04:41.730300 | controller | ok: [instance] 2025-10-02 20:04:41.730387 | controller | 2025-10-02 20:04:41.730536 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ******** 2025-10-02 20:04:41.730623 | controller | Thursday 02 October 2025 20:04:41 +0000 (0:00:00.356) 0:00:23.711 ****** 2025-10-02 20:04:42.085241 | controller | ok: [instance] 2025-10-02 20:04:42.085310 | controller | 2025-10-02 20:04:42.085476 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] ********* 2025-10-02 20:04:42.085609 | controller | Thursday 02 October 2025 20:04:42 +0000 (0:00:00.351) 0:00:24.063 ****** 2025-10-02 20:04:42.450053 | controller | ok: [instance] 2025-10-02 20:04:42.450139 | controller | 2025-10-02 20:04:42.450153 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] ************* 2025-10-02 20:04:42.450300 | controller | Thursday 02 October 2025 20:04:42 +0000 (0:00:00.365) 0:00:24.429 ****** 2025-10-02 20:04:42.812564 | controller | ok: [instance] 2025-10-02 20:04:42.837682 | controller | 2025-10-02 20:04:42.837709 | controller | TASK [libvirt_manager : Manage service for older releases] ********************* 2025-10-02 20:04:42.837718 | controller | Thursday 02 October 2025 20:04:42 +0000 (0:00:00.363) 0:00:24.792 ****** 2025-10-02 20:04:42.837728 | controller | skipping: [instance] 2025-10-02 20:04:43.129381 | controller | 2025-10-02 20:04:43.129422 | controller | TASK [libvirt_manager : Get libvirt group users] ******************************* 2025-10-02 20:04:43.129432 | controller | Thursday 02 October 2025 20:04:42 +0000 (0:00:00.025) 0:00:24.818 ****** 2025-10-02 20:04:43.129442 | controller | ok: [instance] 2025-10-02 20:04:43.566675 | controller | 2025-10-02 20:04:43.566718 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] *************** 2025-10-02 20:04:43.566732 | controller | Thursday 02 October 2025 20:04:43 +0000 (0:00:00.291) 0:00:25.109 ****** 2025-10-02 20:04:43.566747 | controller | ok: [instance] 2025-10-02 20:04:43.920589 | controller | 2025-10-02 20:04:43.920623 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] *** 2025-10-02 20:04:43.920638 | controller | Thursday 02 October 2025 20:04:43 +0000 (0:00:00.437) 0:00:25.547 ****** 2025-10-02 20:04:43.920650 | controller | changed: [instance] 2025-10-02 20:04:44.237195 | controller | 2025-10-02 20:04:44.237257 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] ********* 2025-10-02 20:04:44.237268 | controller | Thursday 02 October 2025 20:04:43 +0000 (0:00:00.350) 0:00:25.897 ****** 2025-10-02 20:04:44.237281 | controller | [WARNING]: Reset is not implemented for this connection 2025-10-02 20:04:44.247918 | controller | changed: [instance] 2025-10-02 20:04:44.315103 | controller | 2025-10-02 20:04:44.315130 | controller | TASK [libvirt_manager : Ensure we reload user env] ***************************** 2025-10-02 20:04:44.315138 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.314) 0:00:26.211 ****** 2025-10-02 20:04:44.315144 | controller | 2025-10-02 20:04:44.315149 | controller | TASK [Create virtual baremetal VMs] ******************************************** 2025-10-02 20:04:44.315155 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.016) 0:00:26.228 ****** 2025-10-02 20:04:44.315165 | controller | 2025-10-02 20:04:44.315190 | controller | TASK [libvirt_manager : Import layout generator if needed] ********************* 2025-10-02 20:04:44.315222 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.067) 0:00:26.296 ****** 2025-10-02 20:04:44.345226 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_layout.yml for instance 2025-10-02 20:04:44.345252 | controller | 2025-10-02 20:04:44.345267 | controller | TASK [libvirt_manager : Chose right parameter for layout definition] *********** 2025-10-02 20:04:44.345395 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.029) 0:00:26.326 ****** 2025-10-02 20:04:44.378527 | controller | ok: [instance] 2025-10-02 20:04:44.378586 | controller | 2025-10-02 20:04:44.378712 | controller | TASK [libvirt_manager : Patch the layout if needed] **************************** 2025-10-02 20:04:44.378804 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.033) 0:00:26.359 ****** 2025-10-02 20:04:44.440831 | controller | skipping: [instance] 2025-10-02 20:04:44.441008 | controller | 2025-10-02 20:04:44.441024 | controller | TASK [libvirt_manager : Enable forwarding in the libvirt zone] ***************** 2025-10-02 20:04:44.888363 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.062) 0:00:26.422 ****** 2025-10-02 20:04:44.888424 | controller | changed: [instance] 2025-10-02 20:04:45.417298 | controller | 2025-10-02 20:04:45.417362 | controller | TASK [libvirt_manager : Enable masquerading for public traffic] **************** 2025-10-02 20:04:45.417374 | controller | Thursday 02 October 2025 20:04:44 +0000 (0:00:00.446) 0:00:26.869 ****** 2025-10-02 20:04:45.417396 | controller | changed: [instance] 2025-10-02 20:04:46.286734 | controller | 2025-10-02 20:04:46.286770 | controller | TASK [libvirt_manager : Ensure firewalld is restarts] ************************** 2025-10-02 20:04:46.286778 | controller | Thursday 02 October 2025 20:04:45 +0000 (0:00:00.517) 0:00:27.386 ****** 2025-10-02 20:04:46.286784 | controller | 2025-10-02 20:04:46.286789 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] ************************** 2025-10-02 20:04:46.286795 | controller | Thursday 02 October 2025 20:04:45 +0000 (0:00:00.010) 0:00:27.397 ****** 2025-10-02 20:04:46.286805 | controller | changed: [instance] 2025-10-02 20:04:46.316744 | controller | 2025-10-02 20:04:46.316779 | controller | TASK [Deploy virtualbmc] ******************************************************* 2025-10-02 20:04:46.316790 | controller | Thursday 02 October 2025 20:04:46 +0000 (0:00:00.869) 0:00:28.267 ****** 2025-10-02 20:04:46.316801 | controller | skipping: [instance] 2025-10-02 20:04:46.346535 | controller | 2025-10-02 20:04:46.346564 | controller | TASK [libvirt_manager : Let the project know we have vbmc available] *********** 2025-10-02 20:04:46.346572 | controller | Thursday 02 October 2025 20:04:46 +0000 (0:00:00.029) 0:00:28.297 ****** 2025-10-02 20:04:46.346582 | controller | skipping: [instance] 2025-10-02 20:04:46.932299 | controller | 2025-10-02 20:04:46.932344 | controller | TASK [libvirt_manager : Create needed workload directory] ********************** 2025-10-02 20:04:46.932352 | controller | Thursday 02 October 2025 20:04:46 +0000 (0:00:00.029) 0:00:28.327 ****** 2025-10-02 20:04:46.932364 | controller | changed: [instance] => (item=workload) 2025-10-02 20:04:47.336552 | controller | changed: [instance] => (item=reproducer-inventory) 2025-10-02 20:04:47.336592 | controller | changed: [instance] => (item=volumes) 2025-10-02 20:04:47.336601 | controller | 2025-10-02 20:04:47.336607 | controller | TASK [libvirt_manager : Allow QEMU on workload directory] ********************** 2025-10-02 20:04:47.336613 | controller | Thursday 02 October 2025 20:04:46 +0000 (0:00:00.585) 0:00:28.913 ****** 2025-10-02 20:04:47.336624 | controller | changed: [instance] => (item=workload) 2025-10-02 20:04:47.336650 | controller | changed: [instance] => (item=volumes) 2025-10-02 20:04:47.336945 | controller | 2025-10-02 20:04:47.417542 | controller | TASK [libvirt_manager : Generate networking data] ****************************** 2025-10-02 20:04:47.417591 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.404) 0:00:29.317 ****** 2025-10-02 20:04:47.417613 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_networking_data.yml for instance 2025-10-02 20:04:47.417659 | controller | 2025-10-02 20:04:47.417671 | controller | TASK [libvirt_manager : Ensure fact is existing, and empty] ******************** 2025-10-02 20:04:47.417784 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.080) 0:00:29.398 ****** 2025-10-02 20:04:47.435010 | controller | ok: [instance] 2025-10-02 20:04:47.435120 | controller | 2025-10-02 20:04:47.435135 | controller | TASK [libvirt_manager : Check if we get an existing interfaces-info.yml] ******* 2025-10-02 20:04:47.435265 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.017) 0:00:29.416 ****** 2025-10-02 20:04:47.622905 | controller | ok: [instance] 2025-10-02 20:04:47.622960 | controller | 2025-10-02 20:04:47.623072 | controller | TASK [libvirt_manager : Load file if exists] *********************************** 2025-10-02 20:04:47.623171 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.187) 0:00:29.604 ****** 2025-10-02 20:04:47.651625 | controller | skipping: [instance] 2025-10-02 20:04:47.651711 | controller | 2025-10-02 20:04:47.651819 | controller | TASK [libvirt_manager : Update fact with existing content] ********************* 2025-10-02 20:04:47.651920 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.028) 0:00:29.632 ****** 2025-10-02 20:04:47.680473 | controller | skipping: [instance] 2025-10-02 20:04:47.680533 | controller | 2025-10-02 20:04:47.680656 | controller | TASK [libvirt_manager : Generate VM list] ************************************** 2025-10-02 20:04:47.680762 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.028) 0:00:29.661 ****** 2025-10-02 20:04:47.735186 | controller | ok: [instance] 2025-10-02 20:04:47.735281 | controller | 2025-10-02 20:04:47.735424 | controller | TASK [libvirt_manager : Generate/update mapping all nodes] ********************* 2025-10-02 20:04:47.735530 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.054) 0:00:29.716 ****** 2025-10-02 20:04:47.830189 | controller | ok: [instance] => (item={'key': 'compute-0', 'value': 'compute'}) 2025-10-02 20:04:47.830284 | controller | ok: [instance] => (item={'key': 'compute-1', 'value': 'compute'}) 2025-10-02 20:04:47.830410 | controller | 2025-10-02 20:04:47.830524 | controller | TASK [libvirt_manager : Append baremetal nodes if needed] ********************** 2025-10-02 20:04:47.830626 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.095) 0:00:29.811 ****** 2025-10-02 20:04:47.863436 | controller | skipping: [instance] 2025-10-02 20:04:47.863533 | controller | 2025-10-02 20:04:47.863638 | controller | TASK [libvirt_manager : Dump MAC mapping] ************************************** 2025-10-02 20:04:47.863737 | controller | Thursday 02 October 2025 20:04:47 +0000 (0:00:00.033) 0:00:29.844 ****** 2025-10-02 20:04:48.234594 | controller | changed: [instance] 2025-10-02 20:04:48.234764 | controller | 2025-10-02 20:04:48.234778 | controller | TASK [libvirt_manager : Inject all VMs in the inventory] *********************** 2025-10-02 20:04:48.234808 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.370) 0:00:30.215 ****** 2025-10-02 20:04:48.337099 | controller | changed: [instance] => (item=Adding compute-0 to computes) 2025-10-02 20:04:48.337315 | controller | changed: [instance] => (item=Adding compute-1 to computes) 2025-10-02 20:04:48.337640 | controller | 2025-10-02 20:04:48.337747 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ****** 2025-10-02 20:04:48.337760 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.102) 0:00:30.318 ****** 2025-10-02 20:04:48.362050 | controller | skipping: [instance] 2025-10-02 20:04:48.362085 | controller | 2025-10-02 20:04:48.362484 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************ 2025-10-02 20:04:48.387082 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.025) 0:00:30.343 ****** 2025-10-02 20:04:48.387105 | controller | skipping: [instance] 2025-10-02 20:04:48.387222 | controller | 2025-10-02 20:04:48.387423 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************ 2025-10-02 20:04:48.387577 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.025) 0:00:30.368 ****** 2025-10-02 20:04:48.414855 | controller | skipping: [instance] 2025-10-02 20:04:48.415004 | controller | 2025-10-02 20:04:48.415090 | controller | TASK [networking_mapper : Load the interfaces info from file] ****************** 2025-10-02 20:04:48.415198 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.027) 0:00:30.396 ****** 2025-10-02 20:04:48.441334 | controller | skipping: [instance] 2025-10-02 20:04:48.441432 | controller | 2025-10-02 20:04:48.441596 | controller | TASK [networking_mapper : Ensure local fact is empty] ************************** 2025-10-02 20:04:48.441757 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.026) 0:00:30.422 ****** 2025-10-02 20:04:48.461959 | controller | ok: [instance] 2025-10-02 20:04:48.462038 | controller | 2025-10-02 20:04:48.462173 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] *** 2025-10-02 20:04:48.462352 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.020) 0:00:30.443 ****** 2025-10-02 20:04:48.541630 | 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-10-02 20:04:48.541751 | controller | 2025-10-02 20:04:48.541854 | controller | TASK [networking_mapper : Gather facts if requested] *************************** 2025-10-02 20:04:48.541988 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.079) 0:00:30.522 ****** 2025-10-02 20:04:48.562669 | controller | skipping: [instance] 2025-10-02 20:04:48.562699 | controller | 2025-10-02 20:04:48.562874 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] ***************** 2025-10-02 20:04:48.563060 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.021) 0:00:30.543 ****** 2025-10-02 20:04:48.798074 | controller | changed: [instance] 2025-10-02 20:04:48.798224 | controller | 2025-10-02 20:04:48.798338 | controller | TASK [networking_mapper : Write the Networking Definition to file] ************* 2025-10-02 20:04:48.798506 | controller | Thursday 02 October 2025 20:04:48 +0000 (0:00:00.235) 0:00:30.778 ****** 2025-10-02 20:04:49.262835 | controller | changed: [instance] 2025-10-02 20:04:49.262912 | controller | 2025-10-02 20:04:49.263057 | controller | TASK [networking_mapper : Call the networking mapper] ************************** 2025-10-02 20:04:49.263240 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.464) 0:00:31.243 ****** 2025-10-02 20:04:49.321491 | controller | ok: [instance] 2025-10-02 20:04:49.321601 | controller | 2025-10-02 20:04:49.321763 | controller | TASK [networking_mapper : Set networking mapper facts] ************************* 2025-10-02 20:04:49.321918 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.059) 0:00:31.302 ****** 2025-10-02 20:04:49.368133 | controller | ok: [instance] 2025-10-02 20:04:49.368315 | controller | 2025-10-02 20:04:49.368544 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] *** 2025-10-02 20:04:49.368651 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.046) 0:00:31.349 ****** 2025-10-02 20:04:49.805415 | controller | changed: [instance] 2025-10-02 20:04:49.805472 | controller | 2025-10-02 20:04:49.805612 | controller | TASK [libvirt_manager : Manage networks if needed] ***************************** 2025-10-02 20:04:49.805737 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.437) 0:00:31.786 ****** 2025-10-02 20:04:49.889687 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks.yml for instance 2025-10-02 20:04:49.889747 | controller | 2025-10-02 20:04:49.889915 | controller | TASK [libvirt_manager : Define the localized variables for performing the tasks here.] *** 2025-10-02 20:04:49.890034 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.084) 0:00:31.870 ****** 2025-10-02 20:04:49.935156 | controller | ok: [instance] => (item=public) 2025-10-02 20:04:49.935285 | controller | 2025-10-02 20:04:49.935495 | controller | TASK [libvirt_manager : Ensure networks are defined] *************************** 2025-10-02 20:04:49.935675 | controller | Thursday 02 October 2025 20:04:49 +0000 (0:00:00.045) 0:00:31.916 ****** 2025-10-02 20:04:50.318836 | controller | changed: [instance] => (item=cifmw-public) 2025-10-02 20:04:50.702710 | controller | 2025-10-02 20:04:50.702745 | controller | TASK [libvirt_manager : Ensure networks are created/started] ******************* 2025-10-02 20:04:50.702753 | controller | Thursday 02 October 2025 20:04:50 +0000 (0:00:00.383) 0:00:32.299 ****** 2025-10-02 20:04:50.702767 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:04:50.961342 | controller | 2025-10-02 20:04:50.961377 | controller | TASK [libvirt_manager : Ensure networks are active] **************************** 2025-10-02 20:04:50.961392 | controller | Thursday 02 October 2025 20:04:50 +0000 (0:00:00.383) 0:00:32.683 ****** 2025-10-02 20:04:50.961403 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:04:51.217762 | controller | 2025-10-02 20:04:51.217794 | controller | TASK [libvirt_manager : Ensure networks enabled to autostart] ****************** 2025-10-02 20:04:51.217802 | controller | Thursday 02 October 2025 20:04:50 +0000 (0:00:00.258) 0:00:32.941 ****** 2025-10-02 20:04:51.217812 | controller | changed: [instance] => (item=cifmw-public) 2025-10-02 20:04:51.284679 | controller | 2025-10-02 20:04:51.284720 | controller | TASK [libvirt_manager : Add a dummy interface to bridges if required] ********** 2025-10-02 20:04:51.284729 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.256) 0:00:33.198 ****** 2025-10-02 20:04:51.284739 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks_dummy_interfaces.yml for instance 2025-10-02 20:04:51.502814 | controller | 2025-10-02 20:04:51.502844 | controller | TASK [libvirt_manager : Fetch present bridge interfaces] *********************** 2025-10-02 20:04:51.502858 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.066) 0:00:33.265 ****** 2025-10-02 20:04:51.502869 | controller | ok: [instance] 2025-10-02 20:04:51.750008 | controller | 2025-10-02 20:04:51.750049 | controller | TASK [libvirt_manager : Fetch bridges ports link info] ************************* 2025-10-02 20:04:51.750057 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.218) 0:00:33.483 ****** 2025-10-02 20:04:51.750067 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:04:51.830195 | controller | 2025-10-02 20:04:51.830277 | controller | TASK [Create dummy interfaces to ensure bridges are UP] ************************ 2025-10-02 20:04:51.830287 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.247) 0:00:33.730 ****** 2025-10-02 20:04:51.830297 | controller | 2025-10-02 20:04:51.870937 | controller | TASK [ci_nmstate : Ensure we have needed facts] ******************************** 2025-10-02 20:04:51.870962 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.080) 0:00:33.810 ****** 2025-10-02 20:04:51.870975 | controller | skipping: [instance] 2025-10-02 20:04:56.717250 | controller | 2025-10-02 20:04:56.717341 | controller | TASK [ci_nmstate : Install required packages on instance] ********************** 2025-10-02 20:04:56.717359 | controller | Thursday 02 October 2025 20:04:51 +0000 (0:00:00.041) 0:00:33.851 ****** 2025-10-02 20:04:56.717370 | controller | changed: [instance] 2025-10-02 20:04:56.952885 | controller | 2025-10-02 20:04:56.952925 | controller | TASK [ci_nmstate : Create the target NMstate dump directory] ******************* 2025-10-02 20:04:56.952935 | controller | Thursday 02 October 2025 20:04:56 +0000 (0:00:04.845) 0:00:38.697 ****** 2025-10-02 20:04:56.952950 | controller | changed: [instance] 2025-10-02 20:04:57.385476 | controller | 2025-10-02 20:04:57.385509 | controller | TASK [ci_nmstate : Save nmstate state for instance] **************************** 2025-10-02 20:04:57.385517 | controller | Thursday 02 October 2025 20:04:56 +0000 (0:00:00.236) 0:00:38.933 ****** 2025-10-02 20:04:57.385527 | controller | changed: [instance] 2025-10-02 20:04:58.402039 | controller | 2025-10-02 20:04:58.402078 | controller | TASK [ci_nmstate : Apply the desidered state on instance] ********************** 2025-10-02 20:04:58.402087 | controller | Thursday 02 October 2025 20:04:57 +0000 (0:00:00.432) 0:00:39.365 ****** 2025-10-02 20:04:58.402097 | controller | changed: [instance] 2025-10-02 20:04:58.811304 | controller | 2025-10-02 20:04:58.811366 | controller | TASK [ci_nmstate : Save nmstate debugging data for instance] ******************* 2025-10-02 20:04:58.811377 | controller | Thursday 02 October 2025 20:04:58 +0000 (0:00:01.016) 0:00:40.382 ****** 2025-10-02 20:04:58.811389 | controller | changed: [instance] 2025-10-02 20:04:58.849648 | controller | 2025-10-02 20:04:58.849683 | controller | TASK [Create extra network configuration] ************************************** 2025-10-02 20:04:58.849695 | controller | Thursday 02 October 2025 20:04:58 +0000 (0:00:00.409) 0:00:40.791 ****** 2025-10-02 20:04:58.849706 | controller | skipping: [instance] 2025-10-02 20:04:58.883013 | controller | 2025-10-02 20:04:58.883049 | controller | TASK [libvirt_manager : Ensure extra networks is in correct zone] ************** 2025-10-02 20:04:58.883058 | controller | Thursday 02 October 2025 20:04:58 +0000 (0:00:00.038) 0:00:40.830 ****** 2025-10-02 20:04:58.883078 | controller | skipping: [instance] 2025-10-02 20:04:59.385785 | controller | 2025-10-02 20:04:59.385819 | controller | TASK [libvirt_manager : Refresh networking facts on host] ********************** 2025-10-02 20:04:59.385827 | controller | Thursday 02 October 2025 20:04:58 +0000 (0:00:00.033) 0:00:40.863 ****** 2025-10-02 20:04:59.385837 | controller | ok: [instance] 2025-10-02 20:04:59.522529 | controller | 2025-10-02 20:04:59.522565 | controller | TASK [libvirt_manager : Build needed network/dnsmasq related content] ********** 2025-10-02 20:04:59.522575 | controller | Thursday 02 October 2025 20:04:59 +0000 (0:00:00.502) 0:00:41.366 ****** 2025-10-02 20:04:59.522594 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:05:00.952463 | controller | 2025-10-02 20:05:00.952501 | controller | TASK [dnsmasq : Install needed packages] *************************************** 2025-10-02 20:05:00.952509 | controller | Thursday 02 October 2025 20:04:59 +0000 (0:00:00.136) 0:00:41.502 ****** 2025-10-02 20:05:00.952520 | controller | ok: [instance] 2025-10-02 20:05:05.490655 | controller | 2025-10-02 20:05:05.490693 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ****** 2025-10-02 20:05:05.490702 | controller | Thursday 02 October 2025 20:05:00 +0000 (0:00:01.430) 0:00:42.932 ****** 2025-10-02 20:05:05.490717 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'}) 2025-10-02 20:05:05.744190 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'}) 2025-10-02 20:05:05.744365 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'}) 2025-10-02 20:05:05.744377 | controller | 2025-10-02 20:05:05.744384 | controller | TASK [dnsmasq : Manage configuration directory] ******************************** 2025-10-02 20:05:05.744390 | controller | Thursday 02 October 2025 20:05:05 +0000 (0:00:04.537) 0:00:47.470 ****** 2025-10-02 20:05:05.744400 | controller | changed: [instance] 2025-10-02 20:05:06.157152 | controller | 2025-10-02 20:05:06.157190 | controller | TASK [dnsmasq : Manage systemd unit file] ************************************** 2025-10-02 20:05:06.157199 | controller | Thursday 02 October 2025 20:05:05 +0000 (0:00:00.254) 0:00:47.724 ****** 2025-10-02 20:05:06.157225 | controller | changed: [instance] 2025-10-02 20:05:06.594442 | controller | 2025-10-02 20:05:06.594478 | controller | TASK [dnsmasq : Manage base configuration file] ******************************** 2025-10-02 20:05:06.594489 | controller | Thursday 02 October 2025 20:05:06 +0000 (0:00:00.412) 0:00:48.137 ****** 2025-10-02 20:05:06.594499 | controller | changed: [instance] 2025-10-02 20:05:06.631992 | controller | 2025-10-02 20:05:06.632025 | controller | TASK [dnsmasq : Render listener configuration] ********************************* 2025-10-02 20:05:06.632036 | controller | Thursday 02 October 2025 20:05:06 +0000 (0:00:00.437) 0:00:48.574 ****** 2025-10-02 20:05:06.632053 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance 2025-10-02 20:05:07.088958 | controller | 2025-10-02 20:05:07.088992 | controller | TASK [dnsmasq : Create listener configuration file] **************************** 2025-10-02 20:05:07.089005 | controller | Thursday 02 October 2025 20:05:06 +0000 (0:00:00.037) 0:00:48.612 ****** 2025-10-02 20:05:07.089021 | controller | changed: [instance] 2025-10-02 20:05:07.111550 | controller | 2025-10-02 20:05:07.111582 | controller | TASK [dnsmasq : Remove listener configuration file] **************************** 2025-10-02 20:05:07.111596 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.453) 0:00:49.066 ****** 2025-10-02 20:05:07.111606 | controller | skipping: [instance] 2025-10-02 20:05:07.149281 | controller | 2025-10-02 20:05:07.149329 | controller | TASK [dnsmasq : Render dns configuration] ************************************** 2025-10-02 20:05:07.149339 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.025) 0:00:49.092 ****** 2025-10-02 20:05:07.149350 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance 2025-10-02 20:05:07.587231 | controller | 2025-10-02 20:05:07.587272 | controller | TASK [dnsmasq : Create dns configuration file] ********************************* 2025-10-02 20:05:07.587285 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.037) 0:00:49.129 ****** 2025-10-02 20:05:07.587308 | controller | changed: [instance] 2025-10-02 20:05:07.609191 | controller | 2025-10-02 20:05:07.609234 | controller | TASK [dnsmasq : Remove dns configuration file] ********************************* 2025-10-02 20:05:07.609243 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.437) 0:00:49.567 ****** 2025-10-02 20:05:07.609253 | controller | skipping: [instance] 2025-10-02 20:05:07.865263 | controller | 2025-10-02 20:05:07.865302 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] *** 2025-10-02 20:05:07.865338 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.022) 0:00:49.590 ****** 2025-10-02 20:05:07.865357 | controller | ok: [instance] => (item=127.0.0.2) 2025-10-02 20:05:08.696908 | controller | 2025-10-02 20:05:08.696946 | controller | TASK [dnsmasq : Enable and start service] ************************************** 2025-10-02 20:05:08.696954 | controller | Thursday 02 October 2025 20:05:07 +0000 (0:00:00.255) 0:00:49.845 ****** 2025-10-02 20:05:08.696965 | controller | changed: [instance] 2025-10-02 20:05:08.718870 | controller | 2025-10-02 20:05:08.718901 | controller | TASK [dnsmasq : Stop service] ************************************************** 2025-10-02 20:05:08.718910 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.831) 0:00:50.677 ****** 2025-10-02 20:05:08.718920 | controller | skipping: [instance] 2025-10-02 20:05:08.740654 | controller | 2025-10-02 20:05:08.740681 | controller | TASK [dnsmasq : Remove unit file] ********************************************** 2025-10-02 20:05:08.740689 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.022) 0:00:50.699 ****** 2025-10-02 20:05:08.740703 | controller | skipping: [instance] 2025-10-02 20:05:08.773437 | controller | 2025-10-02 20:05:08.773460 | controller | TASK [dnsmasq : Remove main configuration files] ******************************* 2025-10-02 20:05:08.773468 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.021) 0:00:50.721 ****** 2025-10-02 20:05:08.773484 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.conf) 2025-10-02 20:05:08.861443 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.d) 2025-10-02 20:05:08.861485 | controller | skipping: [instance] 2025-10-02 20:05:08.861498 | controller | 2025-10-02 20:05:08.861504 | controller | TASK [Create dnsmasq networks] ************************************************* 2025-10-02 20:05:08.861510 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.032) 0:00:50.754 ****** 2025-10-02 20:05:08.861526 | controller | 2025-10-02 20:05:08.895367 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************ 2025-10-02 20:05:08.895394 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.087) 0:00:50.842 ****** 2025-10-02 20:05:08.895405 | controller | ok: [instance] => changed=false 2025-10-02 20:05:08.895609 | controller | msg: All assertions passed 2025-10-02 20:05:08.895793 | controller | 2025-10-02 20:05:08.895942 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] ******************* 2025-10-02 20:05:08.896124 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.034) 0:00:50.876 ****** 2025-10-02 20:05:08.939752 | controller | ok: [instance] => changed=false 2025-10-02 20:05:09.480430 | controller | msg: All assertions passed 2025-10-02 20:05:09.480475 | controller | 2025-10-02 20:05:09.480485 | controller | TASK [dnsmasq : Create network] ************************************************ 2025-10-02 20:05:09.480493 | controller | Thursday 02 October 2025 20:05:08 +0000 (0:00:00.043) 0:00:50.920 ****** 2025-10-02 20:05:09.480514 | controller | changed: [instance] 2025-10-02 20:05:09.502802 | controller | 2025-10-02 20:05:09.502832 | controller | TASK [dnsmasq : Remove network] ************************************************ 2025-10-02 20:05:09.502840 | controller | Thursday 02 October 2025 20:05:09 +0000 (0:00:00.536) 0:00:51.456 ****** 2025-10-02 20:05:09.502850 | controller | skipping: [instance] 2025-10-02 20:05:09.530136 | controller | 2025-10-02 20:05:09.530156 | controller | TASK [dnsmasq : Remove dhcp host files] **************************************** 2025-10-02 20:05:09.530164 | controller | Thursday 02 October 2025 20:05:09 +0000 (0:00:00.026) 0:00:51.483 ****** 2025-10-02 20:05:09.530173 | controller | skipping: [instance] 2025-10-02 20:05:09.888532 | controller | 2025-10-02 20:05:09.888564 | controller | TASK [libvirt_manager : Ensure network is in correct zone] ********************* 2025-10-02 20:05:09.888590 | controller | Thursday 02 October 2025 20:05:09 +0000 (0:00:00.027) 0:00:51.511 ****** 2025-10-02 20:05:09.888602 | controller | changed: [instance] => (item=cifmw-public) 2025-10-02 20:05:09.927387 | controller | 2025-10-02 20:05:09.927419 | controller | TASK [libvirt_manager : Extract IP address from network bridges] *************** 2025-10-02 20:05:09.927427 | controller | Thursday 02 October 2025 20:05:09 +0000 (0:00:00.353) 0:00:51.865 ****** 2025-10-02 20:05:09.927437 | 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-10-02 20:05:10.284143 | controller | 2025-10-02 20:05:10.284183 | controller | TASK [libvirt_manager : Extract IP address from network bridges] *************** 2025-10-02 20:05:10.284193 | controller | Thursday 02 October 2025 20:05:09 +0000 (0:00:00.042) 0:00:51.907 ****** 2025-10-02 20:05:10.284221 | controller | ok: [instance] 2025-10-02 20:05:10.324964 | controller | 2025-10-02 20:05:10.325002 | controller | TASK [libvirt_manager : Set network_bridge_info fact with network and address] *** 2025-10-02 20:05:10.325011 | controller | Thursday 02 October 2025 20:05:10 +0000 (0:00:00.356) 0:00:52.264 ****** 2025-10-02 20:05:10.325022 | controller | ok: [instance] 2025-10-02 20:05:10.325519 | controller | 2025-10-02 20:05:10.729957 | controller | TASK [libvirt_manager : Output _network_data] ********************************** 2025-10-02 20:05:10.730000 | controller | Thursday 02 October 2025 20:05:10 +0000 (0:00:00.040) 0:00:52.305 ****** 2025-10-02 20:05:10.730013 | controller | changed: [instance] 2025-10-02 20:05:11.161778 | controller | 2025-10-02 20:05:11.161867 | controller | TASK [libvirt_manager : Output pub_net] **************************************** 2025-10-02 20:05:11.161877 | controller | Thursday 02 October 2025 20:05:10 +0000 (0:00:00.405) 0:00:52.710 ****** 2025-10-02 20:05:11.161898 | controller | changed: [instance] 2025-10-02 20:05:11.597016 | controller | 2025-10-02 20:05:11.597061 | controller | TASK [libvirt_manager : Output _cifmw_libvirt_manager_layout] ****************** 2025-10-02 20:05:11.597074 | controller | Thursday 02 October 2025 20:05:11 +0000 (0:00:00.429) 0:00:53.140 ****** 2025-10-02 20:05:11.597088 | controller | changed: [instance] 2025-10-02 20:05:11.714069 | controller | 2025-10-02 20:05:11.714104 | controller | TASK [libvirt_manager : Expose patch for networking_mapper] ******************** 2025-10-02 20:05:11.714118 | controller | Thursday 02 October 2025 20:05:11 +0000 (0:00:00.436) 0:00:53.577 ****** 2025-10-02 20:05:11.714133 | controller | ok: [instance] 2025-10-02 20:05:12.161435 | controller | 2025-10-02 20:05:12.161470 | controller | TASK [libvirt_manager : Save networking_mapper patch] ************************** 2025-10-02 20:05:12.161478 | controller | Thursday 02 October 2025 20:05:11 +0000 (0:00:00.117) 0:00:53.694 ****** 2025-10-02 20:05:12.161489 | controller | changed: [instance] 2025-10-02 20:05:12.190520 | controller | 2025-10-02 20:05:12.190561 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ****** 2025-10-02 20:05:12.190570 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.442) 0:00:54.137 ****** 2025-10-02 20:05:12.190581 | controller | skipping: [instance] 2025-10-02 20:05:12.230970 | controller | 2025-10-02 20:05:12.231004 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************ 2025-10-02 20:05:12.231012 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.033) 0:00:54.171 ****** 2025-10-02 20:05:12.231022 | controller | skipping: [instance] 2025-10-02 20:05:12.261721 | controller | 2025-10-02 20:05:12.261757 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************ 2025-10-02 20:05:12.261767 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.040) 0:00:54.211 ****** 2025-10-02 20:05:12.261778 | controller | skipping: [instance] 2025-10-02 20:05:12.293105 | controller | 2025-10-02 20:05:12.293141 | controller | TASK [networking_mapper : Load the interfaces info from file] ****************** 2025-10-02 20:05:12.293149 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.030) 0:00:54.242 ****** 2025-10-02 20:05:12.293160 | controller | skipping: [instance] 2025-10-02 20:05:12.315928 | controller | 2025-10-02 20:05:12.315962 | controller | TASK [networking_mapper : Ensure local fact is empty] ************************** 2025-10-02 20:05:12.315971 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.031) 0:00:54.273 ****** 2025-10-02 20:05:12.315988 | controller | ok: [instance] 2025-10-02 20:05:12.408841 | controller | 2025-10-02 20:05:12.408878 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] *** 2025-10-02 20:05:12.408890 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.022) 0:00:54.296 ****** 2025-10-02 20:05:12.408904 | 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-10-02 20:05:12.430645 | controller | ok: [instance] => (item={'networks': {'public': {'network-v4': '192.168.100.0/24'}}, 'group-templates': {'computes': {'networks': {'public': None}}}}) 2025-10-02 20:05:12.430678 | controller | 2025-10-02 20:05:12.430691 | controller | TASK [networking_mapper : Gather facts if requested] *************************** 2025-10-02 20:05:12.430701 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.092) 0:00:54.389 ****** 2025-10-02 20:05:12.430713 | controller | skipping: [instance] 2025-10-02 20:05:12.721904 | controller | 2025-10-02 20:05:12.721943 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] ***************** 2025-10-02 20:05:12.721952 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.022) 0:00:54.411 ****** 2025-10-02 20:05:12.721963 | controller | ok: [instance] 2025-10-02 20:05:13.238619 | controller | 2025-10-02 20:05:13.238651 | controller | TASK [networking_mapper : Write the Networking Definition to file] ************* 2025-10-02 20:05:13.238659 | controller | Thursday 02 October 2025 20:05:12 +0000 (0:00:00.285) 0:00:54.696 ****** 2025-10-02 20:05:13.238669 | controller | changed: [instance] 2025-10-02 20:05:13.306311 | controller | 2025-10-02 20:05:13.306365 | controller | TASK [networking_mapper : Call the networking mapper] ************************** 2025-10-02 20:05:13.306374 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.521) 0:00:55.218 ****** 2025-10-02 20:05:13.306384 | controller | ok: [instance] 2025-10-02 20:05:13.338558 | controller | 2025-10-02 20:05:13.338593 | controller | TASK [networking_mapper : Set networking mapper facts] ************************* 2025-10-02 20:05:13.338602 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.067) 0:00:55.286 ****** 2025-10-02 20:05:13.338612 | controller | ok: [instance] 2025-10-02 20:05:13.834881 | controller | 2025-10-02 20:05:13.834917 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] *** 2025-10-02 20:05:13.834926 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.032) 0:00:55.319 ****** 2025-10-02 20:05:13.834937 | controller | changed: [instance] 2025-10-02 20:05:13.870147 | controller | 2025-10-02 20:05:13.870181 | controller | TASK [libvirt_manager : Be sure to save current state of networking_mapper environment] *** 2025-10-02 20:05:13.870189 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.495) 0:00:55.814 ****** 2025-10-02 20:05:13.870200 | controller | ok: [instance] 2025-10-02 20:05:13.900475 | controller | 2025-10-02 20:05:13.900501 | controller | TASK [libvirt_manager : Unset patch] ******************************************* 2025-10-02 20:05:13.900509 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.035) 0:00:55.850 ****** 2025-10-02 20:05:13.900519 | controller | ok: [instance] 2025-10-02 20:05:13.928362 | controller | 2025-10-02 20:05:13.928399 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_entries fact] **************** 2025-10-02 20:05:13.928409 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.030) 0:00:55.881 ****** 2025-10-02 20:05:13.928420 | controller | ok: [instance] 2025-10-02 20:05:13.980288 | controller | 2025-10-02 20:05:13.980340 | controller | TASK [libvirt_manager : Reserve IPs on networks] ******************************* 2025-10-02 20:05:13.980354 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.027) 0:00:55.908 ****** 2025-10-02 20:05:13.980365 | 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-10-02 20:05:14.078586 | 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-10-02 20:05:14.078626 | controller | 2025-10-02 20:05:14.078635 | controller | TASK [libvirt_manager : Loop on host IPs] ************************************** 2025-10-02 20:05:14.078641 | controller | Thursday 02 October 2025 20:05:13 +0000 (0:00:00.051) 0:00:55.960 ****** 2025-10-02 20:05:14.078652 | controller | skipping: [instance] => (item=compute-0 - ctlplane) 2025-10-02 20:05:14.213585 | controller | skipping: [instance] => (item=compute-1 - ctlplane) 2025-10-02 20:05:14.213622 | controller | skipping: [instance] 2025-10-02 20:05:14.213630 | controller | 2025-10-02 20:05:14.213636 | controller | TASK [libvirt_manager : Loop on host IPs] ************************************** 2025-10-02 20:05:14.213647 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.098) 0:00:56.058 ****** 2025-10-02 20:05:14.213658 | controller | ok: [instance] => (item=compute-0 - public) 2025-10-02 20:05:14.285280 | controller | ok: [instance] => (item=compute-1 - public) 2025-10-02 20:05:14.285335 | controller | 2025-10-02 20:05:14.285346 | controller | TASK [Inject DHCP entries for net {{ net_name }}] ****************************** 2025-10-02 20:05:14.285352 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.135) 0:00:56.193 ****** 2025-10-02 20:05:14.285368 | controller | 2025-10-02 20:05:14.344461 | controller | TASK [dnsmasq : Ensure we have the right data and type] ************************ 2025-10-02 20:05:14.344499 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.072) 0:00:56.265 ****** 2025-10-02 20:05:14.344512 | controller | ok: [instance] 2025-10-02 20:05:14.414163 | controller | 2025-10-02 20:05:14.414196 | controller | TASK [dnsmasq : Assert we have needed host data] ******************************* 2025-10-02 20:05:14.414204 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.059) 0:00:56.324 ****** 2025-10-02 20:05:14.414226 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:3d:18:b7', 'ips': ['192.168.100.10', '']}) 2025-10-02 20:05:14.473156 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:8b:03:d2', 'ips': ['192.168.100.11', '']}) 2025-10-02 20:05:14.473190 | controller | 2025-10-02 20:05:14.473198 | controller | TASK [dnsmasq : Ensure networks exists] **************************************** 2025-10-02 20:05:14.473204 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.069) 0:00:56.394 ****** 2025-10-02 20:05:14.473227 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/_check_net_status.yml for instance => (item=public) 2025-10-02 20:05:14.715443 | controller | 2025-10-02 20:05:14.715484 | controller | TASK [dnsmasq : Check network file status] ************************************* 2025-10-02 20:05:14.715499 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.059) 0:00:56.453 ****** 2025-10-02 20:05:14.715514 | controller | ok: [instance] 2025-10-02 20:05:14.756744 | controller | 2025-10-02 20:05:14.756775 | controller | TASK [dnsmasq : Assert network exists] ***************************************** 2025-10-02 20:05:14.756788 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.242) 0:00:56.695 ****** 2025-10-02 20:05:14.756799 | controller | ok: [instance] 2025-10-02 20:05:14.781568 | controller | 2025-10-02 20:05:14.781601 | controller | TASK [dnsmasq : Initialize empty dhcp_host_entries] **************************** 2025-10-02 20:05:14.781611 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.041) 0:00:56.737 ****** 2025-10-02 20:05:14.781625 | controller | ok: [instance] 2025-10-02 20:05:14.961017 | controller | 2025-10-02 20:05:14.961050 | controller | TASK [dnsmasq : Compute entry] ************************************************* 2025-10-02 20:05:14.961062 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.025) 0:00:56.762 ****** 2025-10-02 20:05:14.961076 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:3d:18:b7', 'ips': ['192.168.100.10', '']}) 2025-10-02 20:05:15.009464 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:8b:03:d2', 'ips': ['192.168.100.11', '']}) 2025-10-02 20:05:15.009495 | controller | 2025-10-02 20:05:15.009503 | controller | TASK [dnsmasq : Create add/remove sets] **************************************** 2025-10-02 20:05:15.009515 | controller | Thursday 02 October 2025 20:05:14 +0000 (0:00:00.178) 0:00:56.940 ****** 2025-10-02 20:05:15.009526 | controller | ok: [instance] 2025-10-02 20:05:15.926604 | controller | 2025-10-02 20:05:15.926638 | controller | TASK [dnsmasq : Add DHCP entries] ********************************************** 2025-10-02 20:05:15.926646 | controller | Thursday 02 October 2025 20:05:15 +0000 (0:00:00.049) 0:00:56.990 ****** 2025-10-02 20:05:15.926657 | controller | changed: [instance] => (item={'file': 'public_compute-0_52:54:00:3d:18:b7', 'entry': '52:54:00:3d:18:b7,192.168.100.10,compute-0', 'state': 'present'}) 2025-10-02 20:05:15.952186 | controller | changed: [instance] => (item={'file': 'public_compute-1_52:54:01:8b:03:d2', 'entry': '52:54:01:8b:03:d2,192.168.100.11,compute-1', 'state': 'present'}) 2025-10-02 20:05:15.952236 | controller | 2025-10-02 20:05:15.952245 | controller | TASK [dnsmasq : Remove DHCP entries] ******************************************* 2025-10-02 20:05:15.952251 | controller | Thursday 02 October 2025 20:05:15 +0000 (0:00:00.916) 0:00:57.906 ****** 2025-10-02 20:05:15.952266 | controller | skipping: [instance] 2025-10-02 20:05:16.132370 | controller | 2025-10-02 20:05:16.132406 | controller | TASK [libvirt_manager : Create per-network and .utility DNS entries] *********** 2025-10-02 20:05:16.132414 | controller | Thursday 02 October 2025 20:05:15 +0000 (0:00:00.025) 0:00:57.932 ****** 2025-10-02 20:05:16.132425 | controller | ok: [instance] => (item=compute-0) 2025-10-02 20:05:16.225950 | controller | ok: [instance] => (item=compute-1) 2025-10-02 20:05:16.225993 | controller | 2025-10-02 20:05:16.226007 | controller | TASK [Inject VMs in the .utility zone] ***************************************** 2025-10-02 20:05:16.226014 | controller | Thursday 02 October 2025 20:05:16 +0000 (0:00:00.176) 0:00:58.109 ****** 2025-10-02 20:05:16.226025 | controller | 2025-10-02 20:05:16.285067 | controller | TASK [dnsmasq : Assert we have needed host record data] ************************ 2025-10-02 20:05:16.285107 | controller | Thursday 02 October 2025 20:05:16 +0000 (0:00:00.097) 0:00:58.206 ****** 2025-10-02 20:05:16.285123 | controller | ok: [instance] 2025-10-02 20:05:16.455243 | controller | 2025-10-02 20:05:16.455276 | controller | TASK [dnsmasq : Assert each address element have needed data] ****************** 2025-10-02 20:05:16.455296 | controller | Thursday 02 October 2025 20:05:16 +0000 (0:00:00.059) 0:00:58.265 ****** 2025-10-02 20:05:16.455310 | 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-10-02 20:05:17.960187 | controller | ok: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'}) 2025-10-02 20:05:17.960237 | controller | ok: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'}) 2025-10-02 20:05:17.960249 | 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-10-02 20:05:17.960256 | controller | ok: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'}) 2025-10-02 20:05:17.960268 | controller | ok: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'}) 2025-10-02 20:05:17.960273 | controller | 2025-10-02 20:05:17.960279 | controller | TASK [dnsmasq : Add/Remove address] ******************************************** 2025-10-02 20:05:17.960285 | controller | Thursday 02 October 2025 20:05:16 +0000 (0:00:00.169) 0:00:58.434 ****** 2025-10-02 20:05:17.960295 | 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-10-02 20:05:18.393482 | controller | changed: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'}) 2025-10-02 20:05:18.393512 | controller | changed: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'}) 2025-10-02 20:05:18.393526 | 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-10-02 20:05:18.393532 | controller | changed: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'}) 2025-10-02 20:05:18.393538 | controller | changed: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'}) 2025-10-02 20:05:18.393544 | controller | 2025-10-02 20:05:18.393549 | controller | TASK [libvirt_manager : Ensure some domains are local] ************************* 2025-10-02 20:05:18.393561 | controller | Thursday 02 October 2025 20:05:17 +0000 (0:00:01.505) 0:00:59.940 ****** 2025-10-02 20:05:18.393573 | controller | changed: [instance] 2025-10-02 20:05:19.297590 | controller | 2025-10-02 20:05:19.297626 | controller | TASK [libvirt_manager : Ensure dnsmasq is reloaded now] ************************ 2025-10-02 20:05:19.297635 | controller | Thursday 02 October 2025 20:05:18 +0000 (0:00:00.422) 0:01:00.362 ****** 2025-10-02 20:05:19.297645 | controller | 2025-10-02 20:05:19.297652 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] ************************** 2025-10-02 20:05:19.297658 | controller | Thursday 02 October 2025 20:05:18 +0000 (0:00:00.011) 0:01:00.373 ****** 2025-10-02 20:05:19.297668 | controller | changed: [instance] 2025-10-02 20:05:19.686390 | controller | 2025-10-02 20:05:19.686420 | controller | RUNNING HANDLER [dnsmasq : Restart dnsmasq] ************************************ 2025-10-02 20:05:19.686434 | controller | Thursday 02 October 2025 20:05:19 +0000 (0:00:00.904) 0:01:01.278 ****** 2025-10-02 20:05:19.686446 | controller | changed: [instance] 2025-10-02 20:05:20.058180 | controller | 2025-10-02 20:05:20.058211 | controller | RUNNING HANDLER [dnsmasq : Reload dnsmasq] ************************************* 2025-10-02 20:05:20.058231 | controller | Thursday 02 October 2025 20:05:19 +0000 (0:00:00.388) 0:01:01.666 ****** 2025-10-02 20:05:20.058242 | controller | changed: [instance] 2025-10-02 20:05:20.525299 | controller | 2025-10-02 20:05:20.525344 | controller | TASK [libvirt_manager : Create group inventories] ****************************** 2025-10-02 20:05:20.525355 | controller | Thursday 02 October 2025 20:05:20 +0000 (0:00:00.372) 0:01:02.038 ****** 2025-10-02 20:05:20.525365 | controller | changed: [instance] => (item=compute) 2025-10-02 20:05:20.972490 | controller | 2025-10-02 20:05:20.972521 | controller | TASK [libvirt_manager : Create "all" group inventory file] ********************* 2025-10-02 20:05:20.972529 | controller | Thursday 02 October 2025 20:05:20 +0000 (0:00:00.466) 0:01:02.505 ****** 2025-10-02 20:05:20.972546 | controller | changed: [instance] 2025-10-02 20:05:21.014022 | controller | 2025-10-02 20:05:21.014053 | controller | TASK [libvirt_manager : Ensure storage pool is present.] *********************** 2025-10-02 20:05:21.014063 | controller | Thursday 02 October 2025 20:05:20 +0000 (0:00:00.447) 0:01:02.953 ****** 2025-10-02 20:05:21.014075 | controller | skipping: [instance] 2025-10-02 20:05:21.105967 | controller | 2025-10-02 20:05:21.106007 | controller | TASK [libvirt_manager : Ensure images are present] ***************************** 2025-10-02 20:05:21.106015 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.041) 0:01:02.994 ****** 2025-10-02 20:05:21.106025 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/get_image.yml for instance => (item=compute) 2025-10-02 20:05:21.128214 | controller | 2025-10-02 20:05:21.128256 | controller | TASK [libvirt_manager : Ensure directory exists] ******************************* 2025-10-02 20:05:21.128266 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.091) 0:01:03.086 ****** 2025-10-02 20:05:21.128277 | controller | skipping: [instance] 2025-10-02 20:05:21.149581 | controller | 2025-10-02 20:05:21.149604 | controller | TASK [libvirt_manager : Check if base image exists] **************************** 2025-10-02 20:05:21.149614 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.022) 0:01:03.109 ****** 2025-10-02 20:05:21.149626 | controller | skipping: [instance] 2025-10-02 20:05:21.170760 | controller | 2025-10-02 20:05:21.170779 | controller | TASK [libvirt_manager : Download base image] *********************************** 2025-10-02 20:05:21.170794 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.021) 0:01:03.130 ****** 2025-10-02 20:05:21.170806 | controller | skipping: [instance] 2025-10-02 20:05:21.190908 | controller | 2025-10-02 20:05:21.190932 | controller | TASK [libvirt_manager : Check image] ******************************************* 2025-10-02 20:05:21.190939 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.021) 0:01:03.151 ****** 2025-10-02 20:05:21.190949 | controller | skipping: [instance] 2025-10-02 20:05:21.211143 | controller | 2025-10-02 20:05:21.211165 | controller | TASK [libvirt_manager : Assert image status] *********************************** 2025-10-02 20:05:21.211192 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.020) 0:01:03.171 ****** 2025-10-02 20:05:21.211203 | controller | skipping: [instance] 2025-10-02 20:05:21.233858 | controller | 2025-10-02 20:05:21.233882 | controller | TASK [libvirt_manager : Ensure image access rights] **************************** 2025-10-02 20:05:21.233889 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.020) 0:01:03.192 ****** 2025-10-02 20:05:21.233902 | controller | skipping: [instance] 2025-10-02 20:05:21.429162 | controller | 2025-10-02 20:05:21.429196 | controller | TASK [libvirt_manager : Get ssh key state] ************************************* 2025-10-02 20:05:21.429205 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.022) 0:01:03.214 ****** 2025-10-02 20:05:21.429215 | controller | ok: [instance] 2025-10-02 20:05:21.869148 | controller | 2025-10-02 20:05:21.869186 | controller | TASK [libvirt_manager : Create temporary ssh keypair] ************************** 2025-10-02 20:05:21.869196 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.193) 0:01:03.407 ****** 2025-10-02 20:05:21.869206 | controller | changed: [instance] 2025-10-02 20:05:22.177424 | controller | 2025-10-02 20:05:22.177454 | controller | TASK [libvirt_manager : Slurp public key for later use] ************************ 2025-10-02 20:05:22.177462 | controller | Thursday 02 October 2025 20:05:21 +0000 (0:00:00.437) 0:01:03.845 ****** 2025-10-02 20:05:22.177472 | controller | ok: [instance] 2025-10-02 20:05:22.366426 | controller | 2025-10-02 20:05:22.366462 | controller | TASK [libvirt_manager : Slurp private key for later use] *********************** 2025-10-02 20:05:22.366472 | controller | Thursday 02 October 2025 20:05:22 +0000 (0:00:00.308) 0:01:04.154 ****** 2025-10-02 20:05:22.366483 | controller | ok: [instance] 2025-10-02 20:05:22.814979 | controller | 2025-10-02 20:05:22.815016 | controller | TASK [libvirt_manager : Inject cifmw_reproducer_key.pub in hypervisor authorized_keys] *** 2025-10-02 20:05:22.815026 | controller | Thursday 02 October 2025 20:05:22 +0000 (0:00:00.192) 0:01:04.347 ****** 2025-10-02 20:05:22.815039 | controller | changed: [instance] 2025-10-02 20:05:22.839008 | controller | 2025-10-02 20:05:22.839038 | controller | TASK [libvirt_manager : Create fact holding network data for VMs] ************** 2025-10-02 20:05:22.839046 | controller | Thursday 02 October 2025 20:05:22 +0000 (0:00:00.448) 0:01:04.795 ****** 2025-10-02 20:05:22.839056 | controller | ok: [instance] 2025-10-02 20:05:23.102728 | controller | 2025-10-02 20:05:23.102767 | controller | TASK [libvirt_manager : List existing networks] ******************************** 2025-10-02 20:05:23.102780 | controller | Thursday 02 October 2025 20:05:22 +0000 (0:00:00.024) 0:01:04.819 ****** 2025-10-02 20:05:23.102791 | controller | ok: [instance] 2025-10-02 20:05:23.498954 | controller | 2025-10-02 20:05:23.498986 | controller | TASK [libvirt_manager : Gather pool fact] ************************************** 2025-10-02 20:05:23.498995 | controller | Thursday 02 October 2025 20:05:23 +0000 (0:00:00.263) 0:01:05.083 ****** 2025-10-02 20:05:23.499011 | controller | ok: [instance] 2025-10-02 20:05:23.598470 | controller | 2025-10-02 20:05:23.598525 | controller | TASK [libvirt_manager : Create and run VMs] ************************************ 2025-10-02 20:05:23.598537 | controller | Thursday 02 October 2025 20:05:23 +0000 (0:00:00.396) 0:01:05.479 ****** 2025-10-02 20:05:23.598551 | 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-10-02 20:05:23.598584 | 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-10-02 20:05:23.598630 | controller | 2025-10-02 20:05:23.598765 | controller | TASK [libvirt_manager : Create VM image for compute-0] ************************* 2025-10-02 20:05:23.598889 | controller | Thursday 02 October 2025 20:05:23 +0000 (0:00:00.099) 0:01:05.579 ****** 2025-10-02 20:05:23.990450 | controller | changed: [instance] 2025-10-02 20:05:23.990508 | controller | 2025-10-02 20:05:23.990550 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-0] ******** 2025-10-02 20:05:23.990685 | controller | Thursday 02 October 2025 20:05:23 +0000 (0:00:00.392) 0:01:05.971 ****** 2025-10-02 20:05:24.267935 | controller | changed: [instance] 2025-10-02 20:05:24.708981 | controller | 2025-10-02 20:05:24.709023 | controller | TASK [libvirt_manager : Define VMs for type compute-0] ************************* 2025-10-02 20:05:24.709032 | controller | Thursday 02 October 2025 20:05:24 +0000 (0:00:00.276) 0:01:06.248 ****** 2025-10-02 20:05:24.709042 | controller | changed: [instance] 2025-10-02 20:05:24.739083 | controller | 2025-10-02 20:05:24.739110 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-0] *********** 2025-10-02 20:05:24.739123 | controller | Thursday 02 October 2025 20:05:24 +0000 (0:00:00.441) 0:01:06.689 ****** 2025-10-02 20:05:24.739135 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance 2025-10-02 20:05:24.781257 | controller | 2025-10-02 20:05:24.781300 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] **************** 2025-10-02 20:05:24.781310 | controller | Thursday 02 October 2025 20:05:24 +0000 (0:00:00.030) 0:01:06.719 ****** 2025-10-02 20:05:24.781338 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public) 2025-10-02 20:05:25.059108 | controller | 2025-10-02 20:05:25.059144 | controller | TASK [libvirt_manager : Get virtual network information] *********************** 2025-10-02 20:05:25.059153 | controller | Thursday 02 October 2025 20:05:24 +0000 (0:00:00.042) 0:01:06.761 ****** 2025-10-02 20:05:25.059163 | controller | ok: [instance] 2025-10-02 20:05:25.120010 | controller | 2025-10-02 20:05:25.120043 | controller | TASK [libvirt_manager : Create network to bridge mapping] ********************** 2025-10-02 20:05:25.120051 | controller | Thursday 02 October 2025 20:05:25 +0000 (0:00:00.277) 0:01:07.039 ****** 2025-10-02 20:05:25.120068 | controller | ok: [instance] => (item=default) 2025-10-02 20:05:25.401348 | controller | ok: [instance] => (item=crc) 2025-10-02 20:05:25.401385 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:05:25.401394 | controller | 2025-10-02 20:05:25.401400 | controller | TASK [libvirt_manager : Dump domain xml] *************************************** 2025-10-02 20:05:25.401406 | controller | Thursday 02 October 2025 20:05:25 +0000 (0:00:00.059) 0:01:07.099 ****** 2025-10-02 20:05:25.401416 | controller | ok: [instance] 2025-10-02 20:05:25.629802 | controller | 2025-10-02 20:05:25.629843 | controller | TASK [libvirt_manager : Extract networks from XML] ***************************** 2025-10-02 20:05:25.629852 | controller | Thursday 02 October 2025 20:05:25 +0000 (0:00:00.281) 0:01:07.380 ****** 2025-10-02 20:05:25.629863 | controller | ok: [instance] 2025-10-02 20:05:25.986102 | controller | 2025-10-02 20:05:25.986135 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-0] ************ 2025-10-02 20:05:25.986143 | controller | Thursday 02 October 2025 20:05:25 +0000 (0:00:00.229) 0:01:07.610 ****** 2025-10-02 20:05:25.986153 | controller | changed: [instance] 2025-10-02 20:05:26.010274 | controller | 2025-10-02 20:05:26.010304 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-0] ***** 2025-10-02 20:05:26.010313 | controller | Thursday 02 October 2025 20:05:25 +0000 (0:00:00.356) 0:01:07.966 ****** 2025-10-02 20:05:26.010345 | controller | skipping: [instance] 2025-10-02 20:05:26.045985 | controller | 2025-10-02 20:05:26.046012 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-0] ******** 2025-10-02 20:05:26.046020 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.024) 0:01:07.990 ****** 2025-10-02 20:05:26.046033 | controller | skipping: [instance] 2025-10-02 20:05:26.078146 | controller | 2025-10-02 20:05:26.078170 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-0] ************** 2025-10-02 20:05:26.078186 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.035) 0:01:08.026 ****** 2025-10-02 20:05:26.078196 | controller | skipping: [instance] 2025-10-02 20:05:26.113480 | controller | 2025-10-02 20:05:26.113502 | controller | TASK [libvirt_manager : Attach volumes for VM compute-0] *********************** 2025-10-02 20:05:26.113509 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.032) 0:01:08.058 ****** 2025-10-02 20:05:26.113519 | controller | skipping: [instance] 2025-10-02 20:05:26.384394 | controller | 2025-10-02 20:05:26.384426 | controller | TASK [libvirt_manager : Get VM UUID] ******************************************* 2025-10-02 20:05:26.384434 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.035) 0:01:08.093 ****** 2025-10-02 20:05:26.384445 | controller | changed: [instance] 2025-10-02 20:05:26.429775 | controller | 2025-10-02 20:05:26.429809 | controller | TASK [libvirt_manager : Inject UUID in dataset] ******************************** 2025-10-02 20:05:26.429818 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.267) 0:01:08.361 ****** 2025-10-02 20:05:26.429832 | controller | ok: [instance] 2025-10-02 20:05:26.457120 | controller | 2025-10-02 20:05:26.457143 | controller | TASK [libvirt_manager : Create cloud-init ISO] ********************************* 2025-10-02 20:05:26.457151 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.048) 0:01:08.410 ****** 2025-10-02 20:05:26.457164 | controller | skipping: [instance] 2025-10-02 20:05:26.482486 | controller | 2025-10-02 20:05:26.482514 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] *********************** 2025-10-02 20:05:26.482527 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.027) 0:01:08.438 ****** 2025-10-02 20:05:26.482536 | controller | skipping: [instance] 2025-10-02 20:05:26.542740 | controller | 2025-10-02 20:05:26.542775 | controller | TASK [libvirt_manager : Attach additional devices if specified] **************** 2025-10-02 20:05:26.542787 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.025) 0:01:08.463 ****** 2025-10-02 20:05:26.542798 | controller | skipping: [instance] 2025-10-02 20:05:26.847983 | controller | 2025-10-02 20:05:26.848019 | controller | TASK [libvirt_manager : Create VM image for compute-1] ************************* 2025-10-02 20:05:26.848028 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.059) 0:01:08.523 ****** 2025-10-02 20:05:26.848038 | controller | changed: [instance] 2025-10-02 20:05:27.132454 | controller | 2025-10-02 20:05:27.132605 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-1] ******** 2025-10-02 20:05:27.132614 | controller | Thursday 02 October 2025 20:05:26 +0000 (0:00:00.305) 0:01:08.828 ****** 2025-10-02 20:05:27.132624 | controller | changed: [instance] 2025-10-02 20:05:27.473338 | controller | 2025-10-02 20:05:27.473376 | controller | TASK [libvirt_manager : Define VMs for type compute-1] ************************* 2025-10-02 20:05:27.473386 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.284) 0:01:09.112 ****** 2025-10-02 20:05:27.473396 | controller | changed: [instance] 2025-10-02 20:05:27.505009 | controller | 2025-10-02 20:05:27.505035 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-1] *********** 2025-10-02 20:05:27.505043 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.341) 0:01:09.453 ****** 2025-10-02 20:05:27.505053 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance 2025-10-02 20:05:27.547312 | controller | 2025-10-02 20:05:27.547370 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] **************** 2025-10-02 20:05:27.547378 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.032) 0:01:09.485 ****** 2025-10-02 20:05:27.547389 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public) 2025-10-02 20:05:27.816052 | controller | 2025-10-02 20:05:27.816084 | controller | TASK [libvirt_manager : Get virtual network information] *********************** 2025-10-02 20:05:27.816092 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.041) 0:01:09.527 ****** 2025-10-02 20:05:27.816102 | controller | ok: [instance] 2025-10-02 20:05:27.870723 | controller | 2025-10-02 20:05:27.870758 | controller | TASK [libvirt_manager : Create network to bridge mapping] ********************** 2025-10-02 20:05:27.870771 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.268) 0:01:09.796 ****** 2025-10-02 20:05:27.870782 | controller | ok: [instance] => (item=default) 2025-10-02 20:05:28.131151 | controller | ok: [instance] => (item=crc) 2025-10-02 20:05:28.131237 | controller | ok: [instance] => (item=cifmw-public) 2025-10-02 20:05:28.131247 | controller | 2025-10-02 20:05:28.131254 | controller | TASK [libvirt_manager : Dump domain xml] *************************************** 2025-10-02 20:05:28.131266 | controller | Thursday 02 October 2025 20:05:27 +0000 (0:00:00.054) 0:01:09.851 ****** 2025-10-02 20:05:28.131280 | controller | ok: [instance] 2025-10-02 20:05:28.384517 | controller | 2025-10-02 20:05:28.384553 | controller | TASK [libvirt_manager : Extract networks from XML] ***************************** 2025-10-02 20:05:28.384561 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.259) 0:01:10.110 ****** 2025-10-02 20:05:28.384572 | controller | ok: [instance] 2025-10-02 20:05:28.735461 | controller | 2025-10-02 20:05:28.735492 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-1] ************ 2025-10-02 20:05:28.735506 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.250) 0:01:10.361 ****** 2025-10-02 20:05:28.735518 | controller | changed: [instance] 2025-10-02 20:05:28.735761 | controller | 2025-10-02 20:05:28.735780 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-1] ***** 2025-10-02 20:05:28.758799 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.354) 0:01:10.716 ****** 2025-10-02 20:05:28.758822 | controller | skipping: [instance] 2025-10-02 20:05:28.791004 | controller | 2025-10-02 20:05:28.791030 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-1] ******** 2025-10-02 20:05:28.791038 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.023) 0:01:10.739 ****** 2025-10-02 20:05:28.791052 | controller | skipping: [instance] 2025-10-02 20:05:28.824452 | controller | 2025-10-02 20:05:28.824486 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-1] ************** 2025-10-02 20:05:28.824495 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.031) 0:01:10.771 ****** 2025-10-02 20:05:28.824509 | controller | skipping: [instance] 2025-10-02 20:05:28.854289 | controller | 2025-10-02 20:05:28.854333 | controller | TASK [libvirt_manager : Attach volumes for VM compute-1] *********************** 2025-10-02 20:05:28.854344 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.033) 0:01:10.805 ****** 2025-10-02 20:05:28.854355 | controller | skipping: [instance] 2025-10-02 20:05:29.132084 | controller | 2025-10-02 20:05:29.132123 | controller | TASK [libvirt_manager : Get VM UUID] ******************************************* 2025-10-02 20:05:29.132132 | controller | Thursday 02 October 2025 20:05:28 +0000 (0:00:00.030) 0:01:10.835 ****** 2025-10-02 20:05:29.132142 | controller | changed: [instance] 2025-10-02 20:05:29.174078 | controller | 2025-10-02 20:05:29.174117 | controller | TASK [libvirt_manager : Inject UUID in dataset] ******************************** 2025-10-02 20:05:29.174127 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.277) 0:01:11.112 ****** 2025-10-02 20:05:29.174137 | controller | ok: [instance] 2025-10-02 20:05:29.198116 | controller | 2025-10-02 20:05:29.198137 | controller | TASK [libvirt_manager : Create cloud-init ISO] ********************************* 2025-10-02 20:05:29.198146 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.042) 0:01:11.154 ****** 2025-10-02 20:05:29.198155 | controller | skipping: [instance] 2025-10-02 20:05:29.221790 | controller | 2025-10-02 20:05:29.221817 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] *********************** 2025-10-02 20:05:29.221831 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.024) 0:01:11.178 ****** 2025-10-02 20:05:29.221841 | controller | skipping: [instance] 2025-10-02 20:05:29.272137 | controller | 2025-10-02 20:05:29.272174 | controller | TASK [libvirt_manager : Attach additional devices if specified] **************** 2025-10-02 20:05:29.272188 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.023) 0:01:11.202 ****** 2025-10-02 20:05:29.272199 | controller | skipping: [instance] 2025-10-02 20:05:29.318698 | controller | 2025-10-02 20:05:29.318725 | controller | TASK [libvirt_manager : Start (power-on) VMs] ********************************** 2025-10-02 20:05:29.318739 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.050) 0:01:11.252 ****** 2025-10-02 20:05:29.318760 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/start_vms.yml for instance 2025-10-02 20:05:29.608399 | controller | 2025-10-02 20:05:29.608440 | controller | TASK [libvirt_manager : Refresh oooq_pool before starting VMs] ***************** 2025-10-02 20:05:29.608449 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.046) 0:01:11.299 ****** 2025-10-02 20:05:29.608465 | controller | ok: [instance] => (item=crc) 2025-10-02 20:05:30.662770 | controller | 2025-10-02 20:05:30.662811 | controller | TASK [libvirt_manager : Start VMs for type {{ vm_type }}] ********************** 2025-10-02 20:05:30.662820 | controller | Thursday 02 October 2025 20:05:29 +0000 (0:00:00.289) 0:01:11.588 ****** 2025-10-02 20:05:30.662830 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'}) 2025-10-02 20:05:30.782475 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'}) 2025-10-02 20:05:30.782519 | controller | skipping: [instance] 2025-10-02 20:05:30.782529 | controller | 2025-10-02 20:05:30.782535 | controller | TASK [libvirt_manager : Wait for SSH on started VMs] *************************** 2025-10-02 20:05:30.782545 | controller | Thursday 02 October 2025 20:05:30 +0000 (0:00:01.053) 0:01:12.642 ****** 2025-10-02 20:05:30.782555 | controller | skipping: [instance] => (item=compute-0.utility) 2025-10-02 20:05:30.818641 | controller | skipping: [instance] => (item=compute-1.utility) 2025-10-02 20:05:30.818661 | controller | skipping: [instance] 2025-10-02 20:05:30.818668 | controller | 2025-10-02 20:05:30.818674 | controller | TASK [libvirt_manager : Ensure we get SSH on nodes] **************************** 2025-10-02 20:05:30.818680 | controller | Thursday 02 October 2025 20:05:30 +0000 (0:00:00.119) 0:01:12.762 ****** 2025-10-02 20:05:30.818689 | 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-10-02 20:05:30.872655 | 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-10-02 20:05:30.872683 | controller | skipping: [instance] 2025-10-02 20:05:30.872691 | controller | 2025-10-02 20:05:30.872702 | controller | TASK [libvirt_manager : Configure managed VMs] ********************************* 2025-10-02 20:05:30.872710 | controller | Thursday 02 October 2025 20:05:30 +0000 (0:00:00.036) 0:01:12.799 ****** 2025-10-02 20:05:30.872720 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'}) 2025-10-02 20:05:30.922575 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'}) 2025-10-02 20:05:30.922609 | controller | skipping: [instance] 2025-10-02 20:05:30.922618 | controller | 2025-10-02 20:05:30.922630 | controller | TASK [Create VBMC entity] ****************************************************** 2025-10-02 20:05:30.922636 | controller | Thursday 02 October 2025 20:05:30 +0000 (0:00:00.053) 0:01:12.853 ****** 2025-10-02 20:05:30.922650 | controller | skipping: [instance] => (item=compute-0) 2025-10-02 20:05:31.191007 | controller | skipping: [instance] => (item=compute-1) 2025-10-02 20:05:31.191045 | controller | skipping: [instance] 2025-10-02 20:05:31.191053 | controller | 2025-10-02 20:05:31.191059 | controller | TASK [libvirt_manager : List running virtual machines.] ************************ 2025-10-02 20:05:31.191065 | controller | Thursday 02 October 2025 20:05:30 +0000 (0:00:00.049) 0:01:12.902 ****** 2025-10-02 20:05:31.191075 | controller | ok: [instance] 2025-10-02 20:05:31.610769 | controller | 2025-10-02 20:05:31.610806 | controller | TASK [libvirt_manager : Dump UUIDs] ******************************************** 2025-10-02 20:05:31.610815 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.268) 0:01:13.171 ****** 2025-10-02 20:05:31.610830 | controller | changed: [instance] 2025-10-02 20:05:31.647507 | controller | 2025-10-02 20:05:31.647541 | controller | TASK [Ensure fresh vbmc listing] *********************************************** 2025-10-02 20:05:31.647551 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.419) 0:01:13.591 ****** 2025-10-02 20:05:31.647565 | controller | skipping: [instance] 2025-10-02 20:05:31.684704 | controller | 2025-10-02 20:05:31.684742 | controller | TASK [libvirt_manager : Update vbmc related fact] ****************************** 2025-10-02 20:05:31.684751 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.036) 0:01:13.628 ****** 2025-10-02 20:05:31.684764 | controller | skipping: [instance] 2025-10-02 20:05:31.724057 | controller | 2025-10-02 20:05:31.724079 | controller | TASK [libvirt_manager : Dump vbmc known hosts] ********************************* 2025-10-02 20:05:31.724087 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.036) 0:01:13.665 ****** 2025-10-02 20:05:31.724096 | controller | skipping: [instance] 2025-10-02 20:05:31.753445 | controller | 2025-10-02 20:05:31.753474 | controller | TASK [libvirt_manager : Copy authorized_keys] ********************************** 2025-10-02 20:05:31.753486 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.040) 0:01:13.705 ****** 2025-10-02 20:05:31.753496 | controller | skipping: [instance] 2025-10-02 20:05:31.789863 | controller | 2025-10-02 20:05:31.789887 | controller | TASK [libvirt_manager : Enable root access on CRC] ***************************** 2025-10-02 20:05:31.789896 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.029) 0:01:13.734 ****** 2025-10-02 20:05:31.789909 | controller | skipping: [instance] 2025-10-02 20:05:31.879962 | controller | 2025-10-02 20:05:31.879997 | controller | TASK [Generate baremetal-info fact] ******************************************** 2025-10-02 20:05:31.880007 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.036) 0:01:13.770 ****** 2025-10-02 20:05:31.880016 | controller | 2025-10-02 20:05:32.317715 | controller | TASK [reproducer : Ensure directories exist] *********************************** 2025-10-02 20:05:32.317753 | controller | Thursday 02 October 2025 20:05:31 +0000 (0:00:00.090) 0:01:13.860 ****** 2025-10-02 20:05:32.317766 | controller | changed: [instance] => (item=parameters) 2025-10-02 20:05:32.355442 | controller | ok: [instance] => (item=artifacts) 2025-10-02 20:05:32.355469 | controller | 2025-10-02 20:05:32.355481 | controller | TASK [reproducer : Convert VBMC list into a dict for better usage] ************* 2025-10-02 20:05:32.355489 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.437) 0:01:14.297 ****** 2025-10-02 20:05:32.355498 | controller | skipping: [instance] 2025-10-02 20:05:32.580785 | controller | 2025-10-02 20:05:32.580819 | controller | TASK [reproducer : Check if baremetal-info.yml exists] ************************* 2025-10-02 20:05:32.580828 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.038) 0:01:14.336 ****** 2025-10-02 20:05:32.580838 | controller | ok: [instance] 2025-10-02 20:05:32.602031 | controller | 2025-10-02 20:05:32.602078 | controller | TASK [reproducer : Get content of baremetal-info file] ************************* 2025-10-02 20:05:32.602088 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.225) 0:01:14.561 ****** 2025-10-02 20:05:32.602100 | controller | skipping: [instance] 2025-10-02 20:05:32.638292 | controller | 2025-10-02 20:05:32.638338 | controller | TASK [reproducer : Interpret remote file content as yaml] ********************** 2025-10-02 20:05:32.638350 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.021) 0:01:14.582 ****** 2025-10-02 20:05:32.638365 | controller | skipping: [instance] 2025-10-02 20:05:32.666128 | controller | 2025-10-02 20:05:32.666152 | controller | TASK [reproducer : Slurp content of: /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] *** 2025-10-02 20:05:32.666164 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.036) 0:01:14.619 ****** 2025-10-02 20:05:32.666176 | controller | skipping: [instance] 2025-10-02 20:05:32.693096 | controller | 2025-10-02 20:05:32.693125 | controller | TASK [reproducer : Set cifmw_libvirt_manager_mac_map fact from /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] *** 2025-10-02 20:05:32.693134 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.027) 0:01:14.646 ****** 2025-10-02 20:05:32.693144 | controller | skipping: [instance] 2025-10-02 20:05:32.775987 | controller | 2025-10-02 20:05:32.776017 | controller | TASK [reproducer : Generate libvirt_manager_bm_info_data fact] ***************** 2025-10-02 20:05:32.776025 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.027) 0:01:14.673 ****** 2025-10-02 20:05:32.776036 | controller | ok: [instance] => (item={'key': 'cifmw-compute-0', 'value': 'd441a99a-c1a8-4202-bf66-0d65552e51a4'}) 2025-10-02 20:05:33.168820 | controller | ok: [instance] => (item={'key': 'cifmw-compute-1', 'value': '14763b28-42bb-458c-b987-8d43618ae7a7'}) 2025-10-02 20:05:33.168858 | controller | 2025-10-02 20:05:33.168868 | controller | TASK [reproducer : Output baremetal info file] ********************************* 2025-10-02 20:05:33.168874 | controller | Thursday 02 October 2025 20:05:32 +0000 (0:00:00.082) 0:01:14.756 ****** 2025-10-02 20:05:33.168888 | controller | changed: [instance] 2025-10-02 20:05:33.195187 | controller | 2025-10-02 20:05:33.195218 | controller | TASK [reproducer : Output ironic_nodes to file] ******************************** 2025-10-02 20:05:33.195226 | controller | Thursday 02 October 2025 20:05:33 +0000 (0:00:00.392) 0:01:15.149 ****** 2025-10-02 20:05:33.195252 | controller | skipping: [instance] 2025-10-02 20:05:33.274007 | controller | 2025-10-02 20:05:33.274038 | controller | TASK [Run Sushy Emulator role against OCP] ************************************* 2025-10-02 20:05:33.274046 | controller | Thursday 02 October 2025 20:05:33 +0000 (0:00:00.026) 0:01:15.175 ****** 2025-10-02 20:05:33.274056 | controller | 2025-10-02 20:05:33.491375 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] *************** 2025-10-02 20:05:33.491412 | controller | Thursday 02 October 2025 20:05:33 +0000 (0:00:00.078) 0:01:15.254 ****** 2025-10-02 20:05:33.491426 | controller | changed: [instance] 2025-10-02 20:05:38.169055 | controller | 2025-10-02 20:05:38.169098 | controller | TASK [sushy_emulator : Install required packages] ****************************** 2025-10-02 20:05:38.169107 | controller | Thursday 02 October 2025 20:05:33 +0000 (0:00:00.216) 0:01:15.471 ****** 2025-10-02 20:05:38.169118 | controller | changed: [instance] 2025-10-02 20:05:38.169147 | controller | 2025-10-02 20:05:38.169262 | controller | TASK [sushy_emulator : Get ingresses domain] *********************************** 2025-10-02 20:05:38.169428 | controller | Thursday 02 October 2025 20:05:38 +0000 (0:00:04.677) 0:01:20.149 ****** 2025-10-02 20:05:39.384339 | controller | changed: [instance] 2025-10-02 20:05:39.410593 | controller | 2025-10-02 20:05:39.410620 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] ********************* 2025-10-02 20:05:39.410634 | controller | Thursday 02 October 2025 20:05:39 +0000 (0:00:01.215) 0:01:21.364 ****** 2025-10-02 20:05:39.410645 | controller | ok: [instance] 2025-10-02 20:05:39.706782 | controller | 2025-10-02 20:05:39.706826 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] ********************** 2025-10-02 20:05:39.706839 | controller | Thursday 02 October 2025 20:05:39 +0000 (0:00:00.026) 0:01:21.391 ****** 2025-10-02 20:05:39.706850 | controller | changed: [instance] 2025-10-02 20:05:39.910548 | controller | 2025-10-02 20:05:39.910584 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ******************** 2025-10-02 20:05:39.910592 | controller | Thursday 02 October 2025 20:05:39 +0000 (0:00:00.293) 0:01:21.685 ****** 2025-10-02 20:05:39.910602 | controller | ok: [instance] 2025-10-02 20:05:41.197064 | controller | 2025-10-02 20:05:41.197112 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] ******************************* 2025-10-02 20:05:41.197122 | controller | Thursday 02 October 2025 20:05:39 +0000 (0:00:00.205) 0:01:21.891 ****** 2025-10-02 20:05:41.197137 | controller | changed: [instance -> controller-0(192.168.25.229)] 2025-10-02 20:05:41.459107 | controller | 2025-10-02 20:05:41.459142 | controller | TASK [sushy_emulator : Run ssh-keyscan] **************************************** 2025-10-02 20:05:41.459150 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:01.286) 0:01:23.177 ****** 2025-10-02 20:05:41.459161 | controller | changed: [instance] 2025-10-02 20:05:41.852365 | controller | 2025-10-02 20:05:41.852403 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************ 2025-10-02 20:05:41.852411 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.261) 0:01:23.439 ****** 2025-10-02 20:05:41.852422 | controller | changed: [instance] 2025-10-02 20:05:41.884184 | controller | 2025-10-02 20:05:41.884224 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:05:41.884237 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.393) 0:01:23.832 ****** 2025-10-02 20:05:41.884262 | controller | skipping: [instance] 2025-10-02 20:05:41.916226 | controller | 2025-10-02 20:05:41.916261 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:05:41.916276 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.031) 0:01:23.864 ****** 2025-10-02 20:05:41.916286 | controller | skipping: [instance] 2025-10-02 20:05:41.916477 | controller | 2025-10-02 20:05:41.916671 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:05:41.916849 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.032) 0:01:23.897 ****** 2025-10-02 20:05:41.944629 | controller | skipping: [instance] 2025-10-02 20:05:41.944824 | controller | 2025-10-02 20:05:41.944998 | controller | TASK [sushy_emulator : Generate list of filtered VMs] ************************** 2025-10-02 20:05:41.945172 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.028) 0:01:23.925 ****** 2025-10-02 20:05:41.985175 | controller | ok: [instance] 2025-10-02 20:05:41.985411 | controller | 2025-10-02 20:05:41.985596 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] *************************** 2025-10-02 20:05:41.985793 | controller | Thursday 02 October 2025 20:05:41 +0000 (0:00:00.040) 0:01:23.966 ****** 2025-10-02 20:05:42.007409 | controller | skipping: [instance] 2025-10-02 20:05:42.007609 | controller | 2025-10-02 20:05:42.007792 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ******** 2025-10-02 20:05:42.007963 | controller | Thursday 02 October 2025 20:05:42 +0000 (0:00:00.022) 0:01:23.988 ****** 2025-10-02 20:05:42.028041 | controller | skipping: [instance] 2025-10-02 20:05:42.028197 | controller | 2025-10-02 20:05:42.028403 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] *************** 2025-10-02 20:05:42.028556 | controller | Thursday 02 October 2025 20:05:42 +0000 (0:00:00.020) 0:01:24.009 ****** 2025-10-02 20:05:42.049853 | controller | skipping: [instance] 2025-10-02 20:05:42.050023 | controller | 2025-10-02 20:05:42.050226 | controller | TASK [sushy_emulator : Generate htpasswd string] ******************************* 2025-10-02 20:05:42.050440 | controller | Thursday 02 October 2025 20:05:42 +0000 (0:00:00.021) 0:01:24.031 ****** 2025-10-02 20:05:42.272855 | controller | changed: [instance] 2025-10-02 20:05:42.273005 | controller | 2025-10-02 20:05:42.273169 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] ********************* 2025-10-02 20:05:42.273297 | controller | Thursday 02 October 2025 20:05:42 +0000 (0:00:00.222) 0:01:24.253 ****** 2025-10-02 20:05:44.154240 | controller | changed: [instance] => (item=secret) 2025-10-02 20:05:44.174794 | controller | changed: [instance] => (item=configmap) 2025-10-02 20:05:44.174818 | controller | changed: [instance] => (item=pod) 2025-10-02 20:05:44.174826 | controller | changed: [instance] => (item=service) 2025-10-02 20:05:44.174831 | controller | changed: [instance] => (item=route) 2025-10-02 20:05:44.174837 | controller | 2025-10-02 20:05:44.174843 | controller | TASK [sushy_emulator : Write sushy emulator config] **************************** 2025-10-02 20:05:44.174849 | controller | Thursday 02 October 2025 20:05:44 +0000 (0:00:01.881) 0:01:26.134 ****** 2025-10-02 20:05:44.174858 | controller | skipping: [instance] 2025-10-02 20:05:44.199744 | controller | 2025-10-02 20:05:44.199768 | controller | TASK [sushy_emulator : Write htpasswd string to file] ************************** 2025-10-02 20:05:44.199780 | controller | Thursday 02 October 2025 20:05:44 +0000 (0:00:00.021) 0:01:26.155 ****** 2025-10-02 20:05:44.199790 | controller | skipping: [instance] 2025-10-02 20:05:46.466583 | controller | 2025-10-02 20:05:46.466618 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ******************** 2025-10-02 20:05:46.466626 | controller | Thursday 02 October 2025 20:05:44 +0000 (0:00:00.024) 0:01:26.180 ****** 2025-10-02 20:05:46.466636 | controller | changed: [instance] 2025-10-02 20:06:38.380880 | controller | 2025-10-02 20:06:38.380927 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] *** 2025-10-02 20:06:38.380936 | controller | Thursday 02 October 2025 20:05:46 +0000 (0:00:02.266) 0:01:28.447 ****** 2025-10-02 20:06:38.380947 | controller | ok: [instance] 2025-10-02 20:06:40.841755 | controller | 2025-10-02 20:06:40.841785 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] ************************* 2025-10-02 20:06:40.841794 | controller | Thursday 02 October 2025 20:06:38 +0000 (0:00:51.914) 0:02:20.361 ****** 2025-10-02 20:06:40.841809 | controller | changed: [instance] => (item=secret) 2025-10-02 20:07:51.641630 | controller | changed: [instance] => (item=configmap) 2025-10-02 20:07:51.641677 | controller | changed: [instance] => (item=service) 2025-10-02 20:07:51.641685 | controller | changed: [instance] => (item=route) 2025-10-02 20:07:51.641691 | controller | 2025-10-02 20:07:51.641697 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] ********************** 2025-10-02 20:07:51.641703 | controller | Thursday 02 October 2025 20:06:40 +0000 (0:00:02.460) 0:02:22.822 ****** 2025-10-02 20:07:51.641713 | controller | [WARNING]: unknown field "spec.selector" 2025-10-02 20:07:51.642410 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.642896 | controller | "spec.containers[0].readinessProbe.httpGet.initialDelaySeconds" 2025-10-02 20:07:51.642913 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.643359 | controller | "spec.containers[0].readinessProbe.httpGet.periodSeconds" 2025-10-02 20:07:51.643378 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.643829 | controller | "spec.containers[0].livenessProbe.httpGet.initialDelaySeconds" 2025-10-02 20:07:51.643846 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.644263 | controller | "spec.containers[0].livenessProbe.httpGet.failureThreshold" 2025-10-02 20:07:51.644278 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.644725 | controller | "spec.containers[0].livenessProbe.httpGet.periodSeconds" 2025-10-02 20:07:51.644744 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.645145 | controller | "spec.containers[0].startupProbe.httpGet.failureThreshold" 2025-10-02 20:07:51.645161 | controller | [WARNING]: unknown field 2025-10-02 20:07:51.654189 | controller | "spec.containers[0].startupProbe.httpGet.initialDelaySeconds" 2025-10-02 20:07:51.654212 | controller | changed: [instance] 2025-10-02 20:07:51.675036 | controller | 2025-10-02 20:07:51.675062 | controller | TASK [podman : Ensure podman is installed] ************************************* 2025-10-02 20:07:51.675071 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:01:10.812) 0:03:33.634 ****** 2025-10-02 20:07:51.675094 | controller | skipping: [instance] 2025-10-02 20:07:51.700258 | controller | 2025-10-02 20:07:51.700283 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] ********************* 2025-10-02 20:07:51.700291 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.021) 0:03:33.656 ****** 2025-10-02 20:07:51.700301 | controller | skipping: [instance] 2025-10-02 20:07:51.724070 | controller | 2025-10-02 20:07:51.724094 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] ******************* 2025-10-02 20:07:51.724102 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.025) 0:03:33.681 ****** 2025-10-02 20:07:51.724112 | controller | skipping: [instance] 2025-10-02 20:07:51.745981 | controller | 2025-10-02 20:07:51.746004 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] ******************* 2025-10-02 20:07:51.746012 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.023) 0:03:33.705 ****** 2025-10-02 20:07:51.746021 | controller | skipping: [instance] 2025-10-02 20:07:51.772503 | controller | 2025-10-02 20:07:51.772530 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] *** 2025-10-02 20:07:51.772538 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.021) 0:03:33.727 ****** 2025-10-02 20:07:51.772548 | controller | skipping: [instance] 2025-10-02 20:07:51.792546 | controller | 2025-10-02 20:07:51.792570 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ******************** 2025-10-02 20:07:51.792578 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.026) 0:03:33.753 ****** 2025-10-02 20:07:51.792587 | controller | skipping: [instance] 2025-10-02 20:07:51.817140 | controller | 2025-10-02 20:07:51.817165 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] ************** 2025-10-02 20:07:51.817173 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.020) 0:03:33.773 ****** 2025-10-02 20:07:51.817183 | controller | skipping: [instance] 2025-10-02 20:07:51.880491 | controller | 2025-10-02 20:07:51.880535 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] ******************* 2025-10-02 20:07:51.880545 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.024) 0:03:33.798 ****** 2025-10-02 20:07:51.880559 | controller | 2025-10-02 20:07:51.912671 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] *** 2025-10-02 20:07:51.912715 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.063) 0:03:33.861 ****** 2025-10-02 20:07:51.912731 | controller | ok: [instance] 2025-10-02 20:07:51.940364 | controller | 2025-10-02 20:07:51.940403 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] *** 2025-10-02 20:07:51.940412 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.031) 0:03:33.893 ****** 2025-10-02 20:07:51.940422 | controller | skipping: [instance] 2025-10-02 20:07:51.965102 | controller | 2025-10-02 20:07:51.965128 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] *** 2025-10-02 20:07:51.965136 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.027) 0:03:33.921 ****** 2025-10-02 20:07:51.965146 | controller | skipping: [instance] 2025-10-02 20:07:53.169735 | controller | 2025-10-02 20:07:53.169779 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] *** 2025-10-02 20:07:53.169786 | controller | Thursday 02 October 2025 20:07:51 +0000 (0:00:00.024) 0:03:33.946 ****** 2025-10-02 20:07:53.169797 | controller | ok: [instance] 2025-10-02 20:07:55.766418 | controller | 2025-10-02 20:07:55.766449 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] *** 2025-10-02 20:07:55.766457 | controller | Thursday 02 October 2025 20:07:53 +0000 (0:00:01.199) 0:03:35.145 ****** 2025-10-02 20:07:55.766468 | controller | ok: [instance] => (item=d441a99a-c1a8-4202-bf66-0d65552e51a4) 2025-10-02 20:07:55.766529 | controller | ok: [instance] => (item=14763b28-42bb-458c-b987-8d43618ae7a7) 2025-10-02 20:07:55.766693 | controller | 2025-10-02 20:07:55.766726 | controller | TASK [sushy_emulator : Verify baremetal VM power status] *********************** 2025-10-02 20:07:55.766799 | controller | Thursday 02 October 2025 20:07:55 +0000 (0:00:02.601) 0:03:37.747 ****** 2025-10-02 20:07:55.815154 | controller | ok: [instance] => (item=cifmw-compute-0) 2025-10-02 20:07:55.815217 | controller | ok: [instance] => (item=cifmw-compute-1) 2025-10-02 20:07:55.815226 | controller | 2025-10-02 20:07:55.815232 | controller | TASK [Run Sushy Emulator role against podman] ********************************** 2025-10-02 20:07:55.815241 | controller | Thursday 02 October 2025 20:07:55 +0000 (0:00:00.048) 0:03:37.796 ****** 2025-10-02 20:07:55.903827 | controller | 2025-10-02 20:07:55.903889 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] *************** 2025-10-02 20:07:55.904024 | controller | Thursday 02 October 2025 20:07:55 +0000 (0:00:00.088) 0:03:37.884 ****** 2025-10-02 20:07:56.100645 | controller | ok: [instance] 2025-10-02 20:07:56.100699 | controller | 2025-10-02 20:07:56.100772 | controller | TASK [sushy_emulator : Install required packages] ****************************** 2025-10-02 20:07:56.100878 | controller | Thursday 02 October 2025 20:07:56 +0000 (0:00:00.196) 0:03:38.081 ****** 2025-10-02 20:07:57.349100 | controller | ok: [instance] 2025-10-02 20:07:57.349158 | controller | 2025-10-02 20:07:57.349262 | controller | TASK [sushy_emulator : Get ingresses domain] *********************************** 2025-10-02 20:07:57.349404 | controller | Thursday 02 October 2025 20:07:57 +0000 (0:00:01.248) 0:03:39.330 ****** 2025-10-02 20:07:57.368008 | controller | skipping: [instance] 2025-10-02 20:07:57.368067 | controller | 2025-10-02 20:07:57.368184 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] ********************* 2025-10-02 20:07:57.368346 | controller | Thursday 02 October 2025 20:07:57 +0000 (0:00:00.019) 0:03:39.349 ****** 2025-10-02 20:07:57.387283 | controller | skipping: [instance] 2025-10-02 20:07:57.387354 | controller | 2025-10-02 20:07:57.387479 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] ********************** 2025-10-02 20:07:57.387584 | controller | Thursday 02 October 2025 20:07:57 +0000 (0:00:00.019) 0:03:39.368 ****** 2025-10-02 20:07:57.639246 | controller | ok: [instance] 2025-10-02 20:07:57.639288 | controller | 2025-10-02 20:07:57.639354 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ******************** 2025-10-02 20:07:57.639476 | controller | Thursday 02 October 2025 20:07:57 +0000 (0:00:00.251) 0:03:39.620 ****** 2025-10-02 20:07:57.820029 | controller | ok: [instance] 2025-10-02 20:07:57.820085 | controller | 2025-10-02 20:07:57.820192 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] ******************************* 2025-10-02 20:07:57.820295 | controller | Thursday 02 October 2025 20:07:57 +0000 (0:00:00.180) 0:03:39.801 ****** 2025-10-02 20:07:58.980696 | controller | ok: [instance -> controller-0(192.168.25.229)] 2025-10-02 20:07:59.215221 | controller | 2025-10-02 20:07:59.215256 | controller | TASK [sushy_emulator : Run ssh-keyscan] **************************************** 2025-10-02 20:07:59.215265 | controller | Thursday 02 October 2025 20:07:58 +0000 (0:00:01.160) 0:03:40.961 ****** 2025-10-02 20:07:59.215275 | controller | changed: [instance] 2025-10-02 20:07:59.571434 | controller | 2025-10-02 20:07:59.571475 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************ 2025-10-02 20:07:59.571484 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.234) 0:03:41.196 ****** 2025-10-02 20:07:59.571495 | controller | changed: [instance] 2025-10-02 20:07:59.571634 | controller | 2025-10-02 20:07:59.571666 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:07:59.598218 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.356) 0:03:41.552 ****** 2025-10-02 20:07:59.598469 | controller | skipping: [instance] 2025-10-02 20:07:59.623781 | controller | 2025-10-02 20:07:59.623804 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:07:59.623813 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.026) 0:03:41.579 ****** 2025-10-02 20:07:59.623824 | controller | skipping: [instance] 2025-10-02 20:07:59.623883 | controller | 2025-10-02 20:07:59.623902 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] *** 2025-10-02 20:07:59.623915 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.025) 0:03:41.604 ****** 2025-10-02 20:07:59.647148 | controller | skipping: [instance] 2025-10-02 20:07:59.683238 | controller | 2025-10-02 20:07:59.683258 | controller | TASK [sushy_emulator : Generate list of filtered VMs] ************************** 2025-10-02 20:07:59.683266 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.023) 0:03:41.628 ****** 2025-10-02 20:07:59.683275 | controller | ok: [instance] 2025-10-02 20:07:59.701413 | controller | 2025-10-02 20:07:59.701477 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] *************************** 2025-10-02 20:07:59.701488 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.036) 0:03:41.664 ****** 2025-10-02 20:07:59.701502 | controller | skipping: [instance] 2025-10-02 20:07:59.721384 | controller | 2025-10-02 20:07:59.721430 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ******** 2025-10-02 20:07:59.721447 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.018) 0:03:41.682 ****** 2025-10-02 20:07:59.721460 | controller | skipping: [instance] 2025-10-02 20:07:59.742416 | controller | 2025-10-02 20:07:59.742434 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] *************** 2025-10-02 20:07:59.742441 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.019) 0:03:41.702 ****** 2025-10-02 20:07:59.742450 | controller | skipping: [instance] 2025-10-02 20:07:59.742561 | controller | 2025-10-02 20:07:59.742577 | controller | TASK [sushy_emulator : Generate htpasswd string] ******************************* 2025-10-02 20:07:59.742587 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.021) 0:03:41.723 ****** 2025-10-02 20:07:59.965468 | controller | changed: [instance] 2025-10-02 20:07:59.996338 | controller | 2025-10-02 20:07:59.996374 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] ********************* 2025-10-02 20:07:59.996382 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.222) 0:03:41.946 ****** 2025-10-02 20:07:59.996406 | controller | skipping: [instance] => (item=secret) 2025-10-02 20:07:59.996429 | controller | skipping: [instance] => (item=configmap) 2025-10-02 20:07:59.996541 | controller | skipping: [instance] => (item=pod) 2025-10-02 20:07:59.996618 | controller | skipping: [instance] => (item=service) 2025-10-02 20:07:59.996938 | controller | skipping: [instance] => (item=route) 2025-10-02 20:07:59.997059 | controller | skipping: [instance] 2025-10-02 20:07:59.997074 | controller | 2025-10-02 20:07:59.997093 | controller | TASK [sushy_emulator : Write sushy emulator config] **************************** 2025-10-02 20:08:00.354521 | controller | Thursday 02 October 2025 20:07:59 +0000 (0:00:00.031) 0:03:41.977 ****** 2025-10-02 20:08:00.354554 | controller | changed: [instance] 2025-10-02 20:08:00.732759 | controller | 2025-10-02 20:08:00.732805 | controller | TASK [sushy_emulator : Write htpasswd string to file] ************************** 2025-10-02 20:08:00.732821 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.357) 0:03:42.335 ****** 2025-10-02 20:08:00.732832 | controller | changed: [instance] 2025-10-02 20:08:00.752535 | controller | 2025-10-02 20:08:00.752578 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ******************** 2025-10-02 20:08:00.752588 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.377) 0:03:42.713 ****** 2025-10-02 20:08:00.752601 | controller | skipping: [instance] 2025-10-02 20:08:00.771726 | controller | 2025-10-02 20:08:00.771754 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] *** 2025-10-02 20:08:00.771762 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.020) 0:03:42.733 ****** 2025-10-02 20:08:00.771774 | controller | skipping: [instance] 2025-10-02 20:08:00.771780 | controller | 2025-10-02 20:08:00.771787 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] ************************* 2025-10-02 20:08:00.771915 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.019) 0:03:42.752 ****** 2025-10-02 20:08:00.804296 | controller | skipping: [instance] => (item=secret) 2025-10-02 20:08:00.804406 | controller | skipping: [instance] => (item=configmap) 2025-10-02 20:08:00.804543 | controller | skipping: [instance] => (item=service) 2025-10-02 20:08:00.804650 | controller | skipping: [instance] => (item=route) 2025-10-02 20:08:00.804760 | controller | skipping: [instance] 2025-10-02 20:08:00.804858 | controller | 2025-10-02 20:08:00.804959 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] ********************** 2025-10-02 20:08:00.805057 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.032) 0:03:42.785 ****** 2025-10-02 20:08:00.824429 | controller | skipping: [instance] 2025-10-02 20:08:00.824522 | controller | 2025-10-02 20:08:00.824639 | controller | TASK [podman : Ensure podman is installed] ************************************* 2025-10-02 20:08:00.824743 | controller | Thursday 02 October 2025 20:08:00 +0000 (0:00:00.020) 0:03:42.805 ****** 2025-10-02 20:08:02.072739 | controller | ok: [instance] 2025-10-02 20:08:02.072780 | controller | 2025-10-02 20:08:02.072895 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] ********************* 2025-10-02 20:08:02.072980 | controller | Thursday 02 October 2025 20:08:02 +0000 (0:00:01.248) 0:03:44.053 ****** 2025-10-02 20:08:02.286583 | controller | changed: [instance] 2025-10-02 20:08:02.286659 | controller | 2025-10-02 20:08:02.286780 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] ******************* 2025-10-02 20:08:02.286892 | controller | Thursday 02 October 2025 20:08:02 +0000 (0:00:00.213) 0:03:44.267 ****** 2025-10-02 20:08:02.314200 | controller | skipping: [instance] 2025-10-02 20:08:02.314263 | controller | 2025-10-02 20:08:02.314384 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] ******************* 2025-10-02 20:08:02.314516 | controller | Thursday 02 October 2025 20:08:02 +0000 (0:00:00.027) 0:03:44.295 ****** 2025-10-02 20:08:02.339628 | controller | skipping: [instance] 2025-10-02 20:08:02.339691 | controller | 2025-10-02 20:08:02.339786 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] *** 2025-10-02 20:08:02.339883 | controller | Thursday 02 October 2025 20:08:02 +0000 (0:00:00.025) 0:03:44.320 ****** 2025-10-02 20:08:02.369767 | controller | skipping: [instance] 2025-10-02 20:08:02.369884 | controller | 2025-10-02 20:08:02.369895 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ******************** 2025-10-02 20:08:02.369975 | controller | Thursday 02 October 2025 20:08:02 +0000 (0:00:00.029) 0:03:44.350 ****** 2025-10-02 20:08:09.166042 | controller | changed: [instance] 2025-10-02 20:08:09.166107 | controller | 2025-10-02 20:08:09.166284 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] ************** 2025-10-02 20:08:09.166338 | controller | Thursday 02 October 2025 20:08:09 +0000 (0:00:06.796) 0:03:51.147 ****** 2025-10-02 20:08:10.029667 | controller | changed: [instance] 2025-10-02 20:08:10.185595 | controller | 2025-10-02 20:08:10.185646 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] ******************* 2025-10-02 20:08:10.185666 | controller | Thursday 02 October 2025 20:08:10 +0000 (0:00:00.860) 0:03:52.007 ****** 2025-10-02 20:08:10.185679 | controller | 2025-10-02 20:08:10.185699 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] *** 2025-10-02 20:08:10.185781 | controller | Thursday 02 October 2025 20:08:10 +0000 (0:00:00.159) 0:03:52.166 ****** 2025-10-02 20:08:10.224026 | controller | ok: [instance] 2025-10-02 20:08:10.256292 | controller | 2025-10-02 20:08:10.256360 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] *** 2025-10-02 20:08:10.256373 | controller | Thursday 02 October 2025 20:08:10 +0000 (0:00:00.037) 0:03:52.203 ****** 2025-10-02 20:08:10.256409 | controller | skipping: [instance] 2025-10-02 20:08:10.279872 | controller | 2025-10-02 20:08:10.279896 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] *** 2025-10-02 20:08:10.279904 | controller | Thursday 02 October 2025 20:08:10 +0000 (0:00:00.033) 0:03:52.237 ****** 2025-10-02 20:08:10.279914 | controller | skipping: [instance] 2025-10-02 20:08:11.266587 | controller | 2025-10-02 20:08:11.266626 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] *** 2025-10-02 20:08:11.266634 | controller | Thursday 02 October 2025 20:08:10 +0000 (0:00:00.023) 0:03:52.260 ****** 2025-10-02 20:08:11.266647 | controller | ok: [instance] 2025-10-02 20:08:11.266666 | controller | 2025-10-02 20:08:11.266728 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] *** 2025-10-02 20:08:11.266823 | controller | Thursday 02 October 2025 20:08:11 +0000 (0:00:00.986) 0:03:53.247 ****** 2025-10-02 20:08:13.628156 | controller | ok: [instance] => (item=d441a99a-c1a8-4202-bf66-0d65552e51a4) 2025-10-02 20:08:13.628376 | controller | ok: [instance] => (item=14763b28-42bb-458c-b987-8d43618ae7a7) 2025-10-02 20:08:13.628741 | controller | 2025-10-02 20:08:13.628760 | controller | TASK [sushy_emulator : Verify baremetal VM power status] *********************** 2025-10-02 20:08:13.691110 | controller | Thursday 02 October 2025 20:08:13 +0000 (0:00:02.361) 0:03:55.609 ****** 2025-10-02 20:08:13.691147 | controller | ok: [instance] => (item=cifmw-compute-0) 2025-10-02 20:08:13.691216 | controller | ok: [instance] => (item=cifmw-compute-1) 2025-10-02 20:08:13.691355 | controller | 2025-10-02 20:08:13.691503 | controller | PLAY RECAP ********************************************************************* 2025-10-02 20:08:13.691632 | controller | instance : ok=228 changed=86 unreachable=0 failed=0 skipped=105 rescued=0 ignored=0 2025-10-02 20:08:13.691741 | controller | 2025-10-02 20:08:13.691858 | controller | Thursday 02 October 2025 20:08:13 +0000 (0:00:00.062) 0:03:55.671 ****** 2025-10-02 20:08:13.691967 | controller | =============================================================================== 2025-10-02 20:08:13.692097 | controller | sushy_emulator : Apply Sushy Emulator pod resource --------------------- 70.81s 2025-10-02 20:08:13.692206 | controller | sushy_emulator : Check if router pod is running in openshift-ingress namespace -- 51.91s 2025-10-02 20:08:13.692302 | controller | libvirt_manager : Install packages required for using KVM -------------- 11.04s 2025-10-02 20:08:13.692432 | controller | sushy_emulator : Pull Sushy Emulator container image -------------------- 6.80s 2025-10-02 20:08:13.692533 | controller | ci_nmstate : Install required packages on instance ---------------------- 4.85s 2025-10-02 20:08:13.692633 | controller | sushy_emulator : Install required packages ------------------------------ 4.68s 2025-10-02 20:08:13.692734 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 4.54s 2025-10-02 20:08:13.692836 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 2.60s 2025-10-02 20:08:13.692919 | controller | sushy_emulator : Apply Sushy Emulator resources ------------------------- 2.46s 2025-10-02 20:08:13.693009 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 2.36s 2025-10-02 20:08:13.693100 | controller | sushy_emulator : Create the sushy-emulator namespace -------------------- 2.27s 2025-10-02 20:08:13.693190 | controller | sushy_emulator : Write sushy emulator resource loop --------------------- 1.88s 2025-10-02 20:08:13.693282 | controller | libvirt_manager : Restart firewalld ------------------------------------- 1.77s 2025-10-02 20:08:13.693428 | controller | dnsmasq : Add/Remove address -------------------------------------------- 1.51s 2025-10-02 20:08:13.693503 | controller | dnsmasq : Install needed packages --------------------------------------- 1.43s 2025-10-02 20:08:13.693592 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.29s 2025-10-02 20:08:13.693689 | controller | sushy_emulator : Install required packages ------------------------------ 1.25s 2025-10-02 20:08:13.693788 | controller | podman : Ensure podman is installed ------------------------------------- 1.25s 2025-10-02 20:08:13.693876 | controller | sushy_emulator : Get ingresses domain ----------------------------------- 1.22s 2025-10-02 20:08:13.693960 | controller | sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket --- 1.20s 2025-10-02 20:08:13.773843 | controller | INFO Running default > cleanup 2025-10-02 20:08:13.774263 | controller | WARNING Skipping, cleanup playbook not configured. 2025-10-02 20:08:13.774833 | controller | INFO Writing /tmp/report.html report. 2025-10-02 20:08:13.935171 | [controller] Waiting on logger 2025-10-02 20:08:19.104864 | [controller] Waiting on logger 2025-10-02 20:08:29.536894 | [controller] Waiting on logger 2025-10-02 20:08:39.968930 | [controller] Waiting on logger 2025-10-02 20:08:43.847212 | [Zuul] Log Stream did not terminate 2025-10-02 20:08:43.847422 | controller | changed 2025-10-02 20:08:43.873222 | 2025-10-02 20:08:43.873285 | PLAY RECAP 2025-10-02 20:08:43.873323 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-02 20:08:43.873344 | 2025-10-02 20:08:43.933310 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main] 2025-10-02 20:08:43.934200 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main] 2025-10-02 20:08:44.461887 | 2025-10-02 20:08:44.461983 | PLAY [Run ci/playbooks/collect-logs.yml] 2025-10-02 20:08:44.482066 | 2025-10-02 20:08:44.482155 | TASK [Filter out host if needed] 2025-10-02 20:08:44.490624 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller 2025-10-02 20:08:44.495155 | 2025-10-02 20:08:44.495221 | TASK [Ensure file is present] 2025-10-02 20:08:44.878027 | controller | ok 2025-10-02 20:08:44.884693 | 2025-10-02 20:08:44.884775 | TASK [Manage molecule report file] 2025-10-02 20:08:44.907713 | [controller] Waiting on logger 2025-10-02 20:08:54.240879 | [controller] Waiting on logger 2025-10-02 20:09:04.673107 | [controller] Waiting on logger 2025-10-02 20:09:14.053804 | [controller] Waiting on logger 2025-10-02 20:09:15.308037 | [Zuul] Log Stream did not terminate 2025-10-02 20:09:15.308233 | controller | changed 2025-10-02 20:09:15.313310 | 2025-10-02 20:09:15.313372 | TASK [Check if we get ci-framework-data basedir] 2025-10-02 20:09:15.574693 | controller | ok 2025-10-02 20:09:15.579711 | 2025-10-02 20:09:15.579773 | TASK [Create ci-framework-data log directory for zuul] 2025-10-02 20:09:15.954648 | controller | changed 2025-10-02 20:09:15.959935 | 2025-10-02 20:09:15.960016 | TASK [Copy ci-framework interesting files] 2025-10-02 20:09:15.981820 | [controller] Waiting on logger 2025-10-02 20:09:26.369241 | [controller] Waiting on logger 2025-10-02 20:09:36.800908 | [controller] Waiting on logger 2025-10-02 20:09:46.145093 | [controller] Waiting on logger 2025-10-02 20:09:46.253507 | [Zuul] Log Stream did not terminate 2025-10-02 20:09:46.253672 | controller | changed 2025-10-02 20:09:46.258801 | 2025-10-02 20:09:46.258864 | TASK [Get SELinux listing] 2025-10-02 20:09:47.297341 | [controller] Waiting on logger 2025-10-02 20:09:53.556239 | controller | changed 2025-10-02 20:09:53.562015 | 2025-10-02 20:09:53.562082 | TASK [Generate log index] 2025-10-02 20:09:54.674833 | controller | changed 2025-10-02 20:09:54.679767 | 2025-10-02 20:09:54.679834 | TASK [Get some env related data] 2025-10-02 20:09:58.624946 | [controller] Waiting on logger 2025-10-02 20:09:59.705666 | controller | changed 2025-10-02 20:09:59.710937 | 2025-10-02 20:09:59.711003 | TASK [Generate list of logs to collect in home directory] 2025-10-02 20:10:00.085718 | controller | ok: All paths examined 2025-10-02 20:10:00.091489 | 2025-10-02 20:10:00.091554 | LOOP [Copy logs from home directory] 2025-10-02 20:10:00.651240 | controller | changed: 2025-10-02 20:10:00.651944 | controller | { 2025-10-02 20:10:00.652140 | controller | "atime": 1743544925.4788878, 2025-10-02 20:10:00.652163 | controller | "ctime": 1743545329.1409318, 2025-10-02 20:10:00.652182 | controller | "dev": 64513, 2025-10-02 20:10:00.652537 | controller | "gid": 1000, 2025-10-02 20:10:00.652558 | controller | "gr_name": "zuul", 2025-10-02 20:10:00.652867 | controller | "inode": 4518807, 2025-10-02 20:10:00.652885 | controller | "isblk": false, 2025-10-02 20:10:00.652901 | controller | "ischr": false, 2025-10-02 20:10:00.652936 | controller | "isdir": false, 2025-10-02 20:10:00.652956 | controller | "isfifo": false, 2025-10-02 20:10:00.652972 | controller | "isgid": false, 2025-10-02 20:10:00.653134 | controller | "islnk": false, 2025-10-02 20:10:00.653175 | controller | "isreg": true, 2025-10-02 20:10:00.653195 | controller | "issock": false, 2025-10-02 20:10:00.653285 | controller | "isuid": false, 2025-10-02 20:10:00.653302 | controller | "mode": "0644", 2025-10-02 20:10:00.653317 | controller | "mtime": 1743545329.1409318, 2025-10-02 20:10:00.653335 | controller | "nlink": 1, 2025-10-02 20:10:00.653351 | controller | "path": "/home/zuul/crc-setup.log", 2025-10-02 20:10:00.653365 | controller | "pw_name": "zuul", 2025-10-02 20:10:00.653453 | controller | "rgrp": true, 2025-10-02 20:10:00.653472 | controller | "roth": true, 2025-10-02 20:10:00.653488 | controller | "rusr": true, 2025-10-02 20:10:00.653504 | controller | "size": 4108, 2025-10-02 20:10:00.653637 | controller | "uid": 1000, 2025-10-02 20:10:00.653704 | controller | "wgrp": false, 2025-10-02 20:10:00.653721 | controller | "woth": false, 2025-10-02 20:10:00.653736 | controller | "wusr": true, 2025-10-02 20:10:00.653751 | controller | "xgrp": false, 2025-10-02 20:10:00.653765 | controller | "xoth": false, 2025-10-02 20:10:00.653780 | controller | "xusr": false 2025-10-02 20:10:00.653793 | controller | } 2025-10-02 20:10:01.191254 | controller | changed: 2025-10-02 20:10:01.191335 | controller | { 2025-10-02 20:10:01.191361 | controller | "atime": 1743545331.0429637, 2025-10-02 20:10:01.191382 | controller | "ctime": 1743545842.0111232, 2025-10-02 20:10:01.191424 | controller | "dev": 64513, 2025-10-02 20:10:01.191444 | controller | "gid": 1000, 2025-10-02 20:10:01.191492 | controller | "gr_name": "zuul", 2025-10-02 20:10:01.191516 | controller | "inode": 4194437, 2025-10-02 20:10:01.191534 | controller | "isblk": false, 2025-10-02 20:10:01.191551 | controller | "ischr": false, 2025-10-02 20:10:01.191567 | controller | "isdir": false, 2025-10-02 20:10:01.191606 | controller | "isfifo": false, 2025-10-02 20:10:01.191630 | controller | "isgid": false, 2025-10-02 20:10:01.191654 | controller | "islnk": false, 2025-10-02 20:10:01.191668 | controller | "isreg": true, 2025-10-02 20:10:01.191682 | controller | "issock": false, 2025-10-02 20:10:01.191695 | controller | "isuid": false, 2025-10-02 20:10:01.191708 | controller | "mode": "0644", 2025-10-02 20:10:01.191723 | controller | "mtime": 1743545842.0111232, 2025-10-02 20:10:01.191739 | controller | "nlink": 1, 2025-10-02 20:10:01.191754 | controller | "path": "/home/zuul/crc-start.log", 2025-10-02 20:10:01.191768 | controller | "pw_name": "zuul", 2025-10-02 20:10:01.191783 | controller | "rgrp": true, 2025-10-02 20:10:01.191797 | controller | "roth": true, 2025-10-02 20:10:01.191810 | controller | "rusr": true, 2025-10-02 20:10:01.191832 | controller | "size": 4023, 2025-10-02 20:10:01.191845 | controller | "uid": 1000, 2025-10-02 20:10:01.191858 | controller | "wgrp": false, 2025-10-02 20:10:01.191872 | controller | "woth": false, 2025-10-02 20:10:01.191885 | controller | "wusr": true, 2025-10-02 20:10:01.191898 | controller | "xgrp": false, 2025-10-02 20:10:01.191911 | controller | "xoth": false, 2025-10-02 20:10:01.191924 | controller | "xusr": false 2025-10-02 20:10:01.191937 | controller | } 2025-10-02 20:10:01.727840 | controller | changed: 2025-10-02 20:10:01.727931 | controller | { 2025-10-02 20:10:01.728035 | controller | "atime": 1759435184.636894, 2025-10-02 20:10:01.728067 | controller | "ctime": 1759435200.8650644, 2025-10-02 20:10:01.728090 | controller | "dev": 64513, 2025-10-02 20:10:01.728109 | controller | "gid": 1000, 2025-10-02 20:10:01.728125 | controller | "gr_name": "zuul", 2025-10-02 20:10:01.728140 | controller | "inode": 4638651, 2025-10-02 20:10:01.728157 | controller | "isblk": false, 2025-10-02 20:10:01.728173 | controller | "ischr": false, 2025-10-02 20:10:01.728189 | controller | "isdir": false, 2025-10-02 20:10:01.728204 | controller | "isfifo": false, 2025-10-02 20:10:01.728219 | controller | "isgid": false, 2025-10-02 20:10:01.728233 | controller | "islnk": false, 2025-10-02 20:10:01.728250 | controller | "isreg": true, 2025-10-02 20:10:01.728265 | controller | "issock": false, 2025-10-02 20:10:01.728285 | controller | "isuid": false, 2025-10-02 20:10:01.728301 | controller | "mode": "0644", 2025-10-02 20:10:01.728315 | controller | "mtime": 1759435200.8650644, 2025-10-02 20:10:01.728330 | controller | "nlink": 1, 2025-10-02 20:10:01.728345 | controller | "path": "/home/zuul/ansible.log", 2025-10-02 20:10:01.728359 | controller | "pw_name": "zuul", 2025-10-02 20:10:01.728374 | controller | "rgrp": true, 2025-10-02 20:10:01.728451 | controller | "roth": true, 2025-10-02 20:10:01.728475 | controller | "rusr": true, 2025-10-02 20:10:01.728493 | controller | "size": 6749, 2025-10-02 20:10:01.728509 | controller | "uid": 1000, 2025-10-02 20:10:01.728525 | controller | "wgrp": false, 2025-10-02 20:10:01.728541 | controller | "woth": false, 2025-10-02 20:10:01.728557 | controller | "wusr": true, 2025-10-02 20:10:01.728571 | controller | "xgrp": false, 2025-10-02 20:10:01.728597 | controller | "xoth": false, 2025-10-02 20:10:01.728612 | controller | "xusr": false 2025-10-02 20:10:01.728626 | controller | } 2025-10-02 20:10:01.735669 | 2025-10-02 20:10:01.735736 | TASK [Copy crio stats log file] 2025-10-02 20:10:01.750109 | controller | skipping: Conditional result was False 2025-10-02 20:10:01.756051 | 2025-10-02 20:10:01.756129 | TASK [Get SELinux related data] 2025-10-02 20:10:06.784089 | controller | ERROR 2025-10-02 20:10:06.784282 | controller | { 2025-10-02 20:10:06.784315 | controller | "delta": "0:00:00.008586", 2025-10-02 20:10:06.784338 | controller | "end": "2025-10-02 20:10:02.044589", 2025-10-02 20:10:06.784357 | controller | "msg": "non-zero return code", 2025-10-02 20:10:06.784374 | controller | "rc": 1, 2025-10-02 20:10:06.784414 | controller | "start": "2025-10-02 20:10:02.036003" 2025-10-02 20:10:06.784437 | controller | } 2025-10-02 20:10:06.784462 | controller | ERROR: Ignoring Errors 2025-10-02 20:10:06.789755 | 2025-10-02 20:10:06.789819 | TASK [Create system configuration directory] 2025-10-02 20:10:07.044279 | controller | changed 2025-10-02 20:10:07.049742 | 2025-10-02 20:10:07.049808 | TASK [Get some of the system configurations] 2025-10-02 20:10:07.070473 | [controller] Waiting on logger 2025-10-02 20:10:11.104787 | [controller] Waiting on logger 2025-10-02 20:10:14.480897 | controller | changed 2025-10-02 20:10:14.486081 | 2025-10-02 20:10:14.486149 | TASK [Copy generated documentation if available] 2025-10-02 20:10:14.499370 | controller | skipping: Conditional result was False 2025-10-02 20:10:14.504707 | 2025-10-02 20:10:14.504769 | TASK [Copy generated AsciiDoc documentation if available] 2025-10-02 20:10:14.517909 | controller | skipping: Conditional result was False 2025-10-02 20:10:14.523013 | 2025-10-02 20:10:14.523074 | TASK [Compress logs bigger than 2MB] 2025-10-02 20:10:14.546064 | [controller] Waiting on logger 2025-10-02 20:10:25.171602 | controller | changed 2025-10-02 20:10:25.176864 | 2025-10-02 20:10:25.176930 | TASK [Copy files from workspace on node] 2025-10-02 20:10:25.194602 | controller | ok 2025-10-02 20:10:25.215992 | 2025-10-02 20:10:25.216061 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-02 20:10:25.229339 | controller | skipping: Conditional result was False 2025-10-02 20:10:25.234774 | 2025-10-02 20:10:25.234843 | TASK [fetch-output : Set log path for single node] 2025-10-02 20:10:25.262781 | controller | ok 2025-10-02 20:10:25.267669 | 2025-10-02 20:10:25.267735 | LOOP [fetch-output : Ensure local output dirs] 2025-10-02 20:10:25.461260 | controller -> localhost | ok: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/logs" 2025-10-02 20:10:25.461542 | controller -> localhost | changed: All items complete 2025-10-02 20:10:25.461575 | 2025-10-02 20:10:25.636511 | controller -> localhost | changed: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/artifacts" 2025-10-02 20:10:25.815444 | controller -> localhost | changed: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/docs" 2025-10-02 20:10:25.824969 | 2025-10-02 20:10:25.825076 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-02 20:10:26.432823 | controller | changed: 2025-10-02 20:10:26.432995 | controller | .d..t...... ./ 2025-10-02 20:10:26.433025 | controller | >f+++++++++ README.html 2025-10-02 20:10:26.433046 | controller | >f+++++++++ ansible-execution.log 2025-10-02 20:10:26.433066 | controller | >f+++++++++ ansible.log 2025-10-02 20:10:26.433085 | controller | >f+++++++++ crc-setup.log 2025-10-02 20:10:26.433102 | controller | >f+++++++++ crc-start.log 2025-10-02 20:10:26.433118 | controller | >f+++++++++ dmesg.log 2025-10-02 20:10:26.433134 | controller | >f+++++++++ installed-pkgs.log 2025-10-02 20:10:26.433150 | controller | >f+++++++++ python.log 2025-10-02 20:10:26.433164 | controller | >f+++++++++ registries.conf 2025-10-02 20:10:26.433179 | controller | >f+++++++++ report.html 2025-10-02 20:10:26.433194 | controller | >f+++++++++ selinux-denials.log 2025-10-02 20:10:26.433210 | controller | >f+++++++++ selinux-listing.log 2025-10-02 20:10:26.433225 | controller | cd+++++++++ ci-framework-data/ 2025-10-02 20:10:26.433240 | controller | cd+++++++++ ci-framework-data/artifacts/ 2025-10-02 20:10:26.433256 | controller | >f+++++++++ ci-framework-data/artifacts/debug_cifmw_libvirt_manager_layout.yml 2025-10-02 20:10:26.433272 | controller | >f+++++++++ ci-framework-data/artifacts/debug_network_data.yml 2025-10-02 20:10:26.433288 | controller | >f+++++++++ ci-framework-data/artifacts/debug_pub_net_value.txt 2025-10-02 20:10:26.433303 | controller | >f+++++++++ ci-framework-data/artifacts/interfaces-info.yml 2025-10-02 20:10:26.433317 | controller | >f+++++++++ ci-framework-data/artifacts/libvirt-uuids.yml 2025-10-02 20:10:26.433331 | controller | >f+++++++++ ci-framework-data/artifacts/net-map-def-patch.yml 2025-10-02 20:10:26.433345 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml 2025-10-02 20:10:26.433359 | controller | cd+++++++++ ci-framework-data/artifacts/nmstate/ 2025-10-02 20:10:26.433373 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-final-state.yaml 2025-10-02 20:10:26.433410 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-state.yaml 2025-10-02 20:10:26.433431 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/ 2025-10-02 20:10:26.433447 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml 2025-10-02 20:10:26.433463 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/ 2025-10-02 20:10:26.433478 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5 2025-10-02 20:10:26.433492 | controller | cd+++++++++ ci-framework-data/artifacts/sushy_emulator/ 2025-10-02 20:10:26.433507 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/.htpasswd 2025-10-02 20:10:26.433522 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/config.conf 2025-10-02 20:10:26.433536 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/configmap.yaml 2025-10-02 20:10:26.433550 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/known_hosts 2025-10-02 20:10:26.433563 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/pod.yaml 2025-10-02 20:10:26.433577 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/route.yaml 2025-10-02 20:10:26.433609 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/secret.yaml 2025-10-02 20:10:26.433625 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/service.yaml 2025-10-02 20:10:26.433639 | controller | cd+++++++++ ci-framework-data/logs/ 2025-10-02 20:10:26.433654 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log 2025-10-02 20:10:26.433668 | controller | cd+++++++++ registries.conf.d/ 2025-10-02 20:10:26.433682 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf 2025-10-02 20:10:26.433696 | controller | cd+++++++++ system-config/ 2025-10-02 20:10:26.433711 | controller | cd+++++++++ system-config/libvirt/ 2025-10-02 20:10:26.433731 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf 2025-10-02 20:10:26.433746 | controller | >f+++++++++ system-config/libvirt/libvirt.conf 2025-10-02 20:10:26.433761 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf 2025-10-02 20:10:26.433775 | controller | >f+++++++++ system-config/libvirt/network.conf 2025-10-02 20:10:26.433789 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf 2025-10-02 20:10:26.433803 | controller | >f+++++++++ system-config/libvirt/qemu.conf 2025-10-02 20:10:26.433817 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf 2025-10-02 20:10:26.433831 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf 2025-10-02 20:10:26.433845 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf 2025-10-02 20:10:26.433858 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf 2025-10-02 20:10:26.433872 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf 2025-10-02 20:10:26.433886 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf 2025-10-02 20:10:26.433902 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf 2025-10-02 20:10:26.433918 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf 2025-10-02 20:10:26.433932 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf 2025-10-02 20:10:26.433946 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf 2025-10-02 20:10:26.720845 | [controller] Waiting on logger 2025-10-02 20:10:26.882179 | controller | changed: .d..t...... ./ 2025-10-02 20:10:27.305640 | controller | changed: .d..t...... ./ 2025-10-02 20:10:27.316933 | 2025-10-02 20:10:27.317000 | TASK [Return artifact to Zuul] 2025-10-02 20:10:27.346146 | controller | ok 2025-10-02 20:10:27.364794 | 2025-10-02 20:10:27.364851 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host] 2025-10-02 20:10:27.364946 | 2025-10-02 20:10:27.364973 | PLAY RECAP 2025-10-02 20:10:27.365008 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1 2025-10-02 20:10:27.365031 | 2025-10-02 20:10:27.442168 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main] 2025-10-02 20:10:27.442904 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 20:10:27.957970 | 2025-10-02 20:10:27.958073 | PLAY [all] 2025-10-02 20:10:27.976249 | 2025-10-02 20:10:27.976332 | TASK [include_role : fetch-output] 2025-10-02 20:10:28.004337 | controller | ok 2025-10-02 20:10:28.021001 | 2025-10-02 20:10:28.021086 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-02 20:10:28.064963 | controller | skipping: Conditional result was False 2025-10-02 20:10:28.070527 | 2025-10-02 20:10:28.070607 | TASK [fetch-output : Set log path for single node] 2025-10-02 20:10:28.098801 | controller | ok 2025-10-02 20:10:28.103679 | 2025-10-02 20:10:28.103748 | LOOP [fetch-output : Ensure local output dirs] 2025-10-02 20:10:28.418804 | controller -> localhost | ok: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/logs" 2025-10-02 20:10:28.598543 | controller -> localhost | ok: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/artifacts" 2025-10-02 20:10:28.795031 | controller -> localhost | ok: "/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/docs" 2025-10-02 20:10:28.803188 | 2025-10-02 20:10:28.803295 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-02 20:10:29.384156 | controller | ok 2025-10-02 20:10:29.384357 | controller | ok: All items complete 2025-10-02 20:10:29.384430 | 2025-10-02 20:10:29.835369 | controller | ok 2025-10-02 20:10:30.277399 | controller | ok 2025-10-02 20:10:30.297066 | 2025-10-02 20:10:30.297169 | TASK [include_role : fetch-output-openshift] 2025-10-02 20:10:30.310458 | controller | skipping: Conditional result was False 2025-10-02 20:10:30.316191 | 2025-10-02 20:10:30.316258 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-02 20:10:30.649332 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006811 2025-10-02 20:10:30.836744 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006431 2025-10-02 20:10:30.870037 | 2025-10-02 20:10:30.870123 | PLAY [all] 2025-10-02 20:10:30.883960 | 2025-10-02 20:10:30.884031 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-02 20:10:31.338600 | controller | changed 2025-10-02 20:10:31.360011 | 2025-10-02 20:10:31.360065 | PLAY RECAP 2025-10-02 20:10:31.360107 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-02 20:10:31.360129 | 2025-10-02 20:10:31.424934 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 20:10:31.425668 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-02 20:10:31.952917 | 2025-10-02 20:10:31.953016 | PLAY [localhost] 2025-10-02 20:10:31.970070 | 2025-10-02 20:10:31.970144 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-02 20:10:32.270902 | localhost | changed 2025-10-02 20:10:32.275451 | 2025-10-02 20:10:32.275530 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-02 20:10:32.293651 | localhost | ok 2025-10-02 20:10:32.304046 | 2025-10-02 20:10:32.304113 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-02 20:10:32.594979 | localhost | changed 2025-10-02 20:10:32.600426 | 2025-10-02 20:10:32.600496 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-02 20:10:33.134862 | localhost | changed 2025-10-02 20:10:33.139625 | 2025-10-02 20:10:33.139691 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-02 20:10:33.460466 | localhost | Identity added: /var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/tmp/ansible.olape1e2 (/var/lib/zuul/builds/710274db8c2a411badea6a8fba077a23/work/tmp/ansible.olape1e2) 2025-10-02 20:10:33.460646 | localhost | ok: Runtime: 0:00:00.006166 2025-10-02 20:10:33.464808 | 2025-10-02 20:10:33.464873 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-02 20:10:33.674365 | localhost | ok: Runtime: 0:00:00.003782 2025-10-02 20:10:33.678978 | 2025-10-02 20:10:33.679047 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-02 20:10:33.727059 | localhost | changed 2025-10-02 20:10:33.731925 | 2025-10-02 20:10:33.731994 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-02 20:10:34.032844 | localhost | changed 2025-10-02 20:10:34.051939 | 2025-10-02 20:10:34.052010 | PLAY [localhost] 2025-10-02 20:10:34.063123 | 2025-10-02 20:10:34.063185 | TASK [Generate bulk log download script] 2025-10-02 20:10:34.081406 | localhost | ok 2025-10-02 20:10:34.092608 | 2025-10-02 20:10:34.092674 | TASK [local-log-download : Check API endpoint is defined] 2025-10-02 20:10:34.119762 | localhost | ok: All assertions passed 2025-10-02 20:10:34.124098 | 2025-10-02 20:10:34.124161 | TASK [local-log-download : Create download script] 2025-10-02 20:10:34.471615 | localhost -> localhost | changed 2025-10-02 20:10:34.480419 | 2025-10-02 20:10:34.480498 | TASK [Register quick-download link] 2025-10-02 20:10:34.497879 | localhost | ok 2025-10-02 20:10:34.530893 | 2025-10-02 20:10:34.530977 | PLAY [logserver.rdoproject.org] 2025-10-02 20:10:34.540481 | 2025-10-02 20:10:34.540541 | TASK [Set zuul-log-path fact] 2025-10-02 20:10:34.556418 | logserver.rdoproject.org | ok 2025-10-02 20:10:34.565139 | 2025-10-02 20:10:34.565207 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 20:10:34.581784 | logserver.rdoproject.org | ok 2025-10-02 20:10:34.587168 | 2025-10-02 20:10:34.587234 | TASK [upload-logs : Create log directories] 2025-10-02 20:10:36.471547 | logserver.rdoproject.org | changed 2025-10-02 20:10:36.474670 | 2025-10-02 20:10:36.474735 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-02 20:10:36.690322 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004670 2025-10-02 20:10:36.694705 | 2025-10-02 20:10:36.694772 | TASK [upload-logs : Upload logs to log server] 2025-10-02 20:10:38.208100 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-02 20:10:38.210939 | 2025-10-02 20:10:38.211004 | LOOP [upload-logs : Compress console log and json output] 2025-10-02 20:10:38.246480 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 20:10:38.254274 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 20:10:38.258375 | 2025-10-02 20:10:38.258464 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-02 20:10:38.291204 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 20:10:38.291416 | 2025-10-02 20:10:38.294522 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 20:10:38.305608 | 2025-10-02 20:10:38.305682 | LOOP [upload-logs : Upload console log and json output]