2025-10-08 12:11:57.299338 | Job console starting...
2025-10-08 12:11:57.560619 | Updating repositories
2025-10-08 12:11:58.398250 | Preparing job workspace
2025-10-08 12:12:05.631190 | Running Ansible setup...
2025-10-08 12:12:08.673678 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 12:12:09.257295 | 
2025-10-08 12:12:09.257410 | PLAY [localhost]
2025-10-08 12:12:09.269932 | 
2025-10-08 12:12:09.270042 | TASK [Gathering Facts]
2025-10-08 12:12:10.137837 | localhost | ok
2025-10-08 12:12:10.151401 | 
2025-10-08 12:12:10.151490 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-08 12:12:10.489506 | localhost -> localhost | changed
2025-10-08 12:12:10.495599 | 
2025-10-08 12:12:10.495682 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-08 12:12:11.210351 | localhost -> localhost | changed
2025-10-08 12:12:11.220303 | 
2025-10-08 12:12:11.220385 | TASK [Setup log path fact]
2025-10-08 12:12:11.238032 | localhost | ok
2025-10-08 12:12:11.250066 | 
2025-10-08 12:12:11.250189 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 12:12:11.278978 | localhost | ok
2025-10-08 12:12:11.287660 | 
2025-10-08 12:12:11.287747 | TASK [emit-job-header : Print job information]
2025-10-08 12:12:11.316567 | # Job Information
2025-10-08 12:12:11.316722 | Ansible Version: 2.15.12
2025-10-08 12:12:11.316753 | Job: cifmw-molecule-virtualbmc
2025-10-08 12:12:11.316776 | Pipeline: github-check
2025-10-08 12:12:11.316796 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-10-08 12:12:11.316814 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3373
2025-10-08 12:12:11.316832 | Log URL (when completed): https://logserver.rdoproject.org/6b4/rdoproject.org/6b49953303b44f15857a37d9a0682a40/
2025-10-08 12:12:11.316849 | Event ID: 3a070520-a421-11f0-9b5a-2d6f635919d0
2025-10-08 12:12:11.320682 | 
2025-10-08 12:12:11.320751 | LOOP [emit-job-header : Print node information]
2025-10-08 12:12:11.412735 | localhost | ok:
2025-10-08 12:12:11.412897 | localhost | # Node Information
2025-10-08 12:12:11.412959 | localhost | Inventory Hostname: controller
2025-10-08 12:12:11.412989 | localhost | Hostname: np0005476092
2025-10-08 12:12:11.413011 | localhost | Username: zuul
2025-10-08 12:12:11.413034 | localhost | Distro: CentOS 9
2025-10-08 12:12:11.413052 | localhost | Provider: ibm-bm4-nodepool
2025-10-08 12:12:11.413071 | localhost | Region: regionOne
2025-10-08 12:12:11.413089 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-10-08 12:12:11.413107 | localhost | Product Name: OpenStack Compute
2025-10-08 12:12:11.413124 | localhost | Interface IP: 192.168.26.195
2025-10-08 12:12:11.435324 | 
2025-10-08 12:12:11.435416 | PLAY [all]
2025-10-08 12:12:11.442535 | 
2025-10-08 12:12:11.442599 | TASK [Gather network facts]
2025-10-08 12:12:11.807532 | controller | ok
2025-10-08 12:12:11.831142 | 
2025-10-08 12:12:11.831239 | TASK [include_role : start-zuul-console]
2025-10-08 12:12:11.850075 | controller | ok
2025-10-08 12:12:11.863121 | 
2025-10-08 12:12:11.863840 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-08 12:12:12.198787 | controller | ok
2025-10-08 12:12:12.207681 | 
2025-10-08 12:12:12.207756 | TASK [include_role : add-build-sshkey]
2025-10-08 12:12:12.225262 | controller | ok
2025-10-08 12:12:12.238362 | 
2025-10-08 12:12:12.238435 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-08 12:12:12.454378 | controller -> localhost | ok
2025-10-08 12:12:12.459996 | 
2025-10-08 12:12:12.460075 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-08 12:12:12.488523 | controller | ok
2025-10-08 12:12:12.503002 | controller | included: /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-08 12:12:12.508833 | 
2025-10-08 12:12:12.508930 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-08 12:12:12.950560 | controller -> localhost | Generating public/private rsa key pair.
2025-10-08 12:12:12.950730 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/6b49953303b44f15857a37d9a0682a40_id_rsa.
2025-10-08 12:12:12.950765 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/6b49953303b44f15857a37d9a0682a40_id_rsa.pub.
2025-10-08 12:12:12.950792 | controller -> localhost | The key fingerprint is:
2025-10-08 12:12:12.950815 | controller -> localhost | SHA256:dV1bUC1n10dc7IrgblxxAg9LNlw0wk/eTo/sSt+K5Ec zuul-build-sshkey
2025-10-08 12:12:12.950839 | controller -> localhost | The key's randomart image is:
2025-10-08 12:12:12.950859 | controller -> localhost | +---[RSA 3072]----+
2025-10-08 12:12:12.950880 | controller -> localhost | |         o.o+ .*X|
2025-10-08 12:12:12.950899 | controller -> localhost | |          O..o..%|
2025-10-08 12:12:12.950942 | controller -> localhost | |         o.X...*o|
2025-10-08 12:12:12.950967 | controller -> localhost | |         .o.* + .|
2025-10-08 12:12:12.950987 | controller -> localhost | |        S. . O + |
2025-10-08 12:12:12.951006 | controller -> localhost | |          . o E .|
2025-10-08 12:12:12.951024 | controller -> localhost | |         o .oo   |
2025-10-08 12:12:12.951043 | controller -> localhost | |          ++ oo. |
2025-10-08 12:12:12.951061 | controller -> localhost | |         .  +oo..|
2025-10-08 12:12:12.951079 | controller -> localhost | +----[SHA256]-----+
2025-10-08 12:12:12.951126 | controller -> localhost | ok: Runtime: 0:00:00.069029
2025-10-08 12:12:12.957122 | 
2025-10-08 12:12:12.957210 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-08 12:12:12.975419 | controller | ok
2025-10-08 12:12:12.985376 | controller | included: /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-08 12:12:12.993689 | 
2025-10-08 12:12:12.993754 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-08 12:12:13.007632 | controller | skipping: Conditional result was False
2025-10-08 12:12:13.013491 | 
2025-10-08 12:12:13.013557 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-08 12:12:13.387436 | controller | changed
2025-10-08 12:12:13.393865 | 
2025-10-08 12:12:13.393968 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-08 12:12:13.584501 | controller | ok
2025-10-08 12:12:13.589854 | 
2025-10-08 12:12:13.590069 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-08 12:12:14.156230 | controller | changed
2025-10-08 12:12:14.161294 | 
2025-10-08 12:12:14.161361 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-08 12:12:14.748322 | controller | changed
2025-10-08 12:12:14.755262 | 
2025-10-08 12:12:14.755345 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-08 12:12:14.794519 | controller | skipping: Conditional result was False
2025-10-08 12:12:14.802556 | 
2025-10-08 12:12:14.802645 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-08 12:12:15.151173 | controller -> localhost | changed
2025-10-08 12:12:15.161203 | 
2025-10-08 12:12:15.161284 | TASK [add-build-sshkey : Add back temp key]
2025-10-08 12:12:15.411144 | controller -> localhost | Identity added: /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/6b49953303b44f15857a37d9a0682a40_id_rsa (zuul-build-sshkey)
2025-10-08 12:12:15.411325 | controller -> localhost | ok: Runtime: 0:00:00.010069
2025-10-08 12:12:15.417431 | 
2025-10-08 12:12:15.417498 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-08 12:12:15.722696 | controller | ok
2025-10-08 12:12:15.728023 | 
2025-10-08 12:12:15.728093 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-08 12:12:15.751878 | controller | skipping: Conditional result was False
2025-10-08 12:12:15.761616 | 
2025-10-08 12:12:15.761692 | TASK [include_role : validate-host]
2025-10-08 12:12:15.790105 | controller | ok
2025-10-08 12:12:15.810872 | 
2025-10-08 12:12:15.810983 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-08 12:12:15.839520 | controller | ok
2025-10-08 12:12:15.846699 | 
2025-10-08 12:12:15.846814 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-08 12:12:16.078726 | controller -> localhost | ok
2025-10-08 12:12:16.084844 | 
2025-10-08 12:12:16.084944 | TASK [validate-host : Collect information about the host]
2025-10-08 12:12:16.698499 | controller | ok
2025-10-08 12:12:16.708124 | 
2025-10-08 12:12:16.708245 | TASK [validate-host : Sanitize hostname]
2025-10-08 12:12:16.798682 | controller | ok
2025-10-08 12:12:16.806194 | 
2025-10-08 12:12:16.806317 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-08 12:12:17.229918 | controller -> localhost | changed
2025-10-08 12:12:17.236791 | 
2025-10-08 12:12:17.236876 | TASK [validate-host : Collect information about zuul worker]
2025-10-08 12:12:17.571373 | controller | ok
2025-10-08 12:12:17.581904 | 
2025-10-08 12:12:17.582032 | TASK [validate-host : Write out all zuul information for each host]
2025-10-08 12:12:18.400151 | controller -> localhost | changed
2025-10-08 12:12:18.413704 | 
2025-10-08 12:12:18.413772 | TASK [include_role : prepare-workspace-openshift]
2025-10-08 12:12:18.462955 | controller | skipping: Conditional result was False
2025-10-08 12:12:18.471408 | 
2025-10-08 12:12:18.471527 | TASK [include_role : remove-zuul-sshkey]
2025-10-08 12:12:18.485939 | controller | skipping: Conditional result was False
2025-10-08 12:12:18.494841 | 
2025-10-08 12:12:18.494977 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-08 12:12:18.721502 | controller | ok: "logs"
2025-10-08 12:12:18.721744 | controller | ok: All items complete
2025-10-08 12:12:18.721782 | 
2025-10-08 12:12:18.920357 | controller | ok: "artifacts"
2025-10-08 12:12:19.095088 | controller | ok: "docs"
2025-10-08 12:12:19.104197 | 
2025-10-08 12:12:19.104284 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-08 12:12:19.337643 | controller | changed: "logs"
2025-10-08 12:12:19.512780 | controller | changed: "artifacts"
2025-10-08 12:12:19.686559 | controller | changed: "docs"
2025-10-08 12:12:19.734034 | 
2025-10-08 12:12:19.734122 | PLAY RECAP
2025-10-08 12:12:19.734184 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 12:12:19.734214 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 12:12:19.734235 | 
2025-10-08 12:12:19.879551 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 12:12:19.880315 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 12:12:20.518522 | 
2025-10-08 12:12:20.518642 | PLAY [all]
2025-10-08 12:12:20.543767 | 
2025-10-08 12:12:20.543860 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 12:12:20.604041 | controller | ok
2025-10-08 12:12:20.610232 | 
2025-10-08 12:12:20.610324 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 12:12:20.988744 | controller | changed
2025-10-08 12:12:20.994970 | 
2025-10-08 12:12:20.996476 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 12:12:21.857499 | controller | changed
2025-10-08 12:12:21.867248 | 
2025-10-08 12:12:21.867338 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-10-08 12:12:22.234986 | controller | changed:
2025-10-08 12:12:22.235262 | controller | {
2025-10-08 12:12:22.235305 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-10-08 12:12:22.235338 | controller | }
2025-10-08 12:12:22.431557 | controller | changed:
2025-10-08 12:12:22.431655 | controller | {
2025-10-08 12:12:22.431690 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-10-08 12:12:22.431711 | controller | }
2025-10-08 12:12:22.641585 | controller | changed:
2025-10-08 12:12:22.641680 | controller | {
2025-10-08 12:12:22.641707 | 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-08 12:12:22.641729 | controller | }
2025-10-08 12:12:22.853249 | controller | changed:
2025-10-08 12:12:22.853333 | controller | {
2025-10-08 12:12:22.853361 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-10-08 12:12:22.853382 | controller | }
2025-10-08 12:12:23.072243 | controller | changed:
2025-10-08 12:12:23.072329 | controller | {
2025-10-08 12:12:23.072358 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-10-08 12:12:23.072379 | controller | }
2025-10-08 12:12:23.284844 | controller | changed:
2025-10-08 12:12:23.284945 | controller | {
2025-10-08 12:12:23.284978 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-10-08 12:12:23.285002 | controller | }
2025-10-08 12:12:23.499070 | controller | changed:
2025-10-08 12:12:23.499188 | controller | {
2025-10-08 12:12:23.499226 | 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-08 12:12:23.499256 | controller | }
2025-10-08 12:12:23.702079 | controller | changed:
2025-10-08 12:12:23.702177 | controller | {
2025-10-08 12:12:23.702209 | 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-08 12:12:23.702231 | controller | }
2025-10-08 12:12:23.903577 | controller | changed:
2025-10-08 12:12:23.903669 | controller | {
2025-10-08 12:12:23.903707 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-10-08 12:12:23.903731 | controller | }
2025-10-08 12:12:24.119449 | controller | changed:
2025-10-08 12:12:24.119540 | controller | {
2025-10-08 12:12:24.119567 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-10-08 12:12:24.119589 | controller | }
2025-10-08 12:12:24.326539 | controller | changed:
2025-10-08 12:12:24.326631 | controller | {
2025-10-08 12:12:24.326662 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-10-08 12:12:24.326684 | controller | }
2025-10-08 12:12:24.557601 | controller | changed:
2025-10-08 12:12:24.557691 | controller | {
2025-10-08 12:12:24.557719 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-10-08 12:12:24.557741 | controller | }
2025-10-08 12:12:24.742230 | controller | changed:
2025-10-08 12:12:24.742325 | controller | {
2025-10-08 12:12:24.742355 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-10-08 12:12:24.742377 | controller | }
2025-10-08 12:12:24.951800 | controller | changed:
2025-10-08 12:12:24.951999 | controller | {
2025-10-08 12:12:24.952030 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-10-08 12:12:24.952053 | controller | }
2025-10-08 12:12:25.171867 | controller | changed:
2025-10-08 12:12:25.172039 | controller | {
2025-10-08 12:12:25.172068 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-10-08 12:12:25.172091 | controller | }
2025-10-08 12:12:25.399842 | controller | changed:
2025-10-08 12:12:25.399960 | controller | {
2025-10-08 12:12:25.399991 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-10-08 12:12:25.400013 | controller | }
2025-10-08 12:12:25.618168 | controller | changed:
2025-10-08 12:12:25.618247 | controller | {
2025-10-08 12:12:25.618275 | 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-08 12:12:25.618297 | controller | }
2025-10-08 12:12:25.834417 | controller | changed:
2025-10-08 12:12:25.834495 | controller | {
2025-10-08 12:12:25.834521 | 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-08 12:12:25.834551 | controller | }
2025-10-08 12:12:26.064479 | controller | changed:
2025-10-08 12:12:26.064557 | controller | {
2025-10-08 12:12:26.064585 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-10-08 12:12:26.064607 | controller | }
2025-10-08 12:12:26.290279 | controller | changed:
2025-10-08 12:12:26.290368 | controller | {
2025-10-08 12:12:26.290395 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-10-08 12:12:26.290417 | controller | }
2025-10-08 12:12:26.504061 | controller | changed:
2025-10-08 12:12:26.504167 | controller | {
2025-10-08 12:12:26.504194 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-10-08 12:12:26.504216 | controller | }
2025-10-08 12:12:26.728889 | controller | changed:
2025-10-08 12:12:26.728990 | controller | {
2025-10-08 12:12:26.729018 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-10-08 12:12:26.729039 | controller | }
2025-10-08 12:12:26.935090 | controller | changed:
2025-10-08 12:12:26.935198 | controller | {
2025-10-08 12:12:26.935227 | 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-08 12:12:26.935248 | controller | }
2025-10-08 12:12:27.145024 | controller | changed:
2025-10-08 12:12:27.145180 | controller | {
2025-10-08 12:12:27.145208 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-10-08 12:12:27.145230 | controller | }
2025-10-08 12:12:27.353188 | controller | changed:
2025-10-08 12:12:27.353273 | controller | {
2025-10-08 12:12:27.353302 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-10-08 12:12:27.353322 | controller | }
2025-10-08 12:12:27.557955 | controller | changed:
2025-10-08 12:12:27.558178 | controller | {
2025-10-08 12:12:27.558221 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-10-08 12:12:27.558246 | controller | }
2025-10-08 12:12:27.579662 | 
2025-10-08 12:12:27.579791 | TASK [Set timezone to UTC]
2025-10-08 12:12:27.995570 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-10-08 12:12:28.001858 | 
2025-10-08 12:12:28.001971 | TASK [Create nodepool directory]
2025-10-08 12:12:28.224773 | controller | changed
2025-10-08 12:12:28.231706 | 
2025-10-08 12:12:28.231833 | TASK [Create nodepool sub_nodes file]
2025-10-08 12:12:28.779499 | controller | changed
2025-10-08 12:12:28.784936 | 
2025-10-08 12:12:28.785037 | TASK [Create nodepool sub_nodes_private file]
2025-10-08 12:12:29.352365 | controller | changed
2025-10-08 12:12:29.359659 | 
2025-10-08 12:12:29.359784 | LOOP [Populate nodepool sub_nodes file]
2025-10-08 12:12:29.405809 | 
2025-10-08 12:12:29.406071 | LOOP [Populate nodepool sub_nodes_private file]
2025-10-08 12:12:29.460865 | 
2025-10-08 12:12:29.461699 | TASK [Create nodepool primary file]
2025-10-08 12:12:29.489006 | controller | skipping: Conditional result was False
2025-10-08 12:12:29.496573 | 
2025-10-08 12:12:29.496687 | TASK [Create nodepool node_private for this node]
2025-10-08 12:12:30.133657 | controller | changed
2025-10-08 12:12:30.142784 | 
2025-10-08 12:12:30.142880 | LOOP [Copy ssh keys to nodepool directory]
2025-10-08 12:12:30.470120 | controller | ok: Item: id_rsa Runtime: 0:00:00.006002
2025-10-08 12:12:30.470342 | 
2025-10-08 12:12:30.641884 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005231
2025-10-08 12:12:30.648438 | 
2025-10-08 12:12:30.648533 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-10-08 12:12:31.256166 | controller | changed
2025-10-08 12:12:31.262249 | 
2025-10-08 12:12:31.262329 | TASK [Validate sudoers config after edits]
2025-10-08 12:12:31.510795 | controller | /etc/sudoers: parsed OK
2025-10-08 12:12:31.510892 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-10-08 12:12:31.510906 | controller | /etc/sudoers.d/zuul: parsed OK
2025-10-08 12:12:31.510912 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-10-08 12:12:31.797651 | controller | ok: Runtime: 0:00:00.005974
2025-10-08 12:12:31.803430 | 
2025-10-08 12:12:31.803497 | TASK [Show the environment passed in to job shell scripts]
2025-10-08 12:12:32.024277 | controller | SHELL=/bin/bash
2025-10-08 12:12:32.024401 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-10-08 12:12:32.024415 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-10-08 12:12:32.024422 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/73/3373/1a7b2ae378ead444d1ed756aace4ec009d749f1a
2025-10-08 12:12:32.024429 | controller | PWD=/home/zuul
2025-10-08 12:12:32.024435 | controller | ZUUL_PIPELINE=github-check
2025-10-08 12:12:32.024441 | controller | LOGNAME=zuul
2025-10-08 12:12:32.024446 | controller | XDG_SESSION_TYPE=tty
2025-10-08 12:12:32.024452 | controller | _=/usr/bin/env
2025-10-08 12:12:32.024457 | controller | MOTD_SHOWN=pam
2025-10-08 12:12:32.024462 | controller | HOME=/home/zuul
2025-10-08 12:12:32.024468 | controller | LANG=en_US.UTF-8
2025-10-08 12:12:32.024473 | controller | SSH_CONNECTION=192.168.26.12 39114 192.168.26.195 22
2025-10-08 12:12:32.024479 | 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-08 12:12:32.024488 | controller | ZUUL_CHANGE_IDS=3373,1a7b2ae378ead444d1ed756aace4ec009d749f1a
2025-10-08 12:12:32.024493 | controller | WORKSPACE=/home/zuul/workspace
2025-10-08 12:12:32.024499 | controller | XDG_SESSION_CLASS=user
2025-10-08 12:12:32.024511 | controller | SELINUX_ROLE_REQUESTED=
2025-10-08 12:12:32.024517 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-10-08 12:12:32.024522 | controller | USER=zuul
2025-10-08 12:12:32.024528 | controller | ZUUL_VOTING=True
2025-10-08 12:12:32.024533 | controller | BUILD_TIMEOUT=1800000
2025-10-08 12:12:32.024539 | controller | SELINUX_USE_CURRENT_RANGE=
2025-10-08 12:12:32.024544 | controller | SHLVL=1
2025-10-08 12:12:32.024550 | controller | ZUUL_PATCHSET=1a7b2ae378ead444d1ed756aace4ec009d749f1a
2025-10-08 12:12:32.024555 | controller | XDG_SESSION_ID=1
2025-10-08 12:12:32.024561 | controller | ZUUL_BRANCH=main
2025-10-08 12:12:32.024566 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-10-08 12:12:32.024571 | controller | SSH_CLIENT=192.168.26.12 39114 22
2025-10-08 12:12:32.024576 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-10-08 12:12:32.024582 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-10-08 12:12:32.024588 | controller | which_declare=declare -f
2025-10-08 12:12:32.024594 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-10-08 12:12:32.024600 | controller | SELINUX_LEVEL_REQUESTED=
2025-10-08 12:12:32.024606 | controller | ZUUL_CHANGE=3373
2025-10-08 12:12:32.024611 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-10-08 12:12:32.024630 | controller | ZUUL_UUID=6b49953303b44f15857a37d9a0682a40
2025-10-08 12:12:32.024638 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-10-08 12:12:32.024644 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-10-08 12:12:32.024650 | controller | }
2025-10-08 12:12:32.333703 | controller | ok: Runtime: 0:00:00.006600
2025-10-08 12:12:32.339291 | 
2025-10-08 12:12:32.339359 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-10-08 12:12:32.353144 | controller | skipping: Conditional result was False
2025-10-08 12:12:32.358716 | 
2025-10-08 12:12:32.358792 | TASK [Symlink /home/zuul-worker/workspace]
2025-10-08 12:12:32.885794 | controller | skipping: Conditional result was False
2025-10-08 12:12:32.898384 | 
2025-10-08 12:12:32.898472 | TASK [Ensure legacy workspace directory]
2025-10-08 12:12:33.115709 | controller | changed
2025-10-08 12:12:33.135726 | 
2025-10-08 12:12:33.135796 | PLAY RECAP
2025-10-08 12:12:33.135843 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 12:12:33.135867 | 
2025-10-08 12:12:33.261177 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 12:12:33.261959 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 12:12:33.893362 | 
2025-10-08 12:12:33.893483 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-10-08 12:12:33.939481 | 
2025-10-08 12:12:33.939611 | TASK [Create zuul-output directory]
2025-10-08 12:12:34.291337 | controller | changed
2025-10-08 12:12:34.298748 | 
2025-10-08 12:12:34.299735 | TASK [Slurp Zuul inventory test]
2025-10-08 12:12:34.590477 | controller -> localhost | ok
2025-10-08 12:12:34.597626 | 
2025-10-08 12:12:34.597715 | TASK [Save zuul inventory]
2025-10-08 12:12:35.379478 | controller | changed
2025-10-08 12:12:35.384415 | 
2025-10-08 12:12:35.384501 | TASK [Save zuul vars without the change_message]
2025-10-08 12:12:35.999830 | controller | changed
2025-10-08 12:12:36.031336 | 
2025-10-08 12:12:36.031417 | PLAY RECAP
2025-10-08 12:12:36.031460 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 12:12:36.031485 | 
2025-10-08 12:12:36.111408 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 12:12:36.112452 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 12:12:36.691704 | 
2025-10-08 12:12:36.691817 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-10-08 12:12:36.713088 | 
2025-10-08 12:12:36.713196 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-10-08 12:12:36.743934 | controller | ok
2025-10-08 12:12:36.760972 | 
2025-10-08 12:12:36.761087 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 12:12:36.784867 | controller | skipping: Conditional result was False
2025-10-08 12:12:36.790749 | 
2025-10-08 12:12:36.790840 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 12:12:37.146495 | controller | ok
2025-10-08 12:12:37.151895 | 
2025-10-08 12:12:37.151985 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 12:12:37.800495 | controller | ok
2025-10-08 12:12:37.813988 | 
2025-10-08 12:12:37.814089 | TASK [Prepare workspace]
2025-10-08 12:12:37.833244 | controller | ok
2025-10-08 12:12:37.850556 | 
2025-10-08 12:12:37.850662 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-08 12:12:38.177258 | controller | ok
2025-10-08 12:12:38.207221 | 
2025-10-08 12:12:38.207332 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-08 12:12:40.290974 | controller | Output suppressed because no_log was given
2025-10-08 12:12:40.302614 | 
2025-10-08 12:12:40.302706 | LOOP [Create zuul-output directory]
2025-10-08 12:12:40.496046 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-10-08 12:12:40.667433 | controller | ok: "/home/zuul/zuul-output/logs"
2025-10-08 12:12:40.685561 | 
2025-10-08 12:12:40.685650 | TASK [Install required packages]
2025-10-08 12:13:44.630283 | controller | changed
2025-10-08 12:13:44.636628 | 
2025-10-08 12:13:44.636716 | TASK [Install venv]
2025-10-08 12:14:47.901404 | controller | changed
2025-10-08 12:14:47.931720 | 
2025-10-08 12:14:47.931797 | PLAY RECAP
2025-10-08 12:14:47.931842 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 12:14:47.931866 | 
2025-10-08 12:14:48.035985 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 12:14:48.036840 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 12:14:48.628581 | 
2025-10-08 12:14:48.628739 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-10-08 12:14:48.649806 | 
2025-10-08 12:14:48.649903 | TASK [Gather required facts]
2025-10-08 12:14:49.156057 | controller | ok
2025-10-08 12:14:49.161633 | 
2025-10-08 12:14:49.161716 | TASK [Load environment var if instructed to]
2025-10-08 12:14:49.186517 | controller | skipping: Conditional result was False
2025-10-08 12:14:49.192838 | 
2025-10-08 12:14:49.192971 | TASK [Run molecule]
2025-10-08 12:14:50.187784 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-10-08 12:14:50.260306 | controller | INFO     Performing prerun with role_name_check=0...
2025-10-08 12:15:07.683441 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.683920 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.684360 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.684822 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.685295 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+1a7b2ae3 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 1.0.0+1a7b2ae3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.685758 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.686210 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.686652 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.687124 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.687548 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.688035 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.688461 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.688934 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.689362 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.689819 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/f9b5a8/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:15:07.699575 | controller | INFO     Running default > prepare
2025-10-08 12:15:08.448523 | controller |
2025-10-08 12:15:08.448595 | controller | PLAY [Prepare] *****************************************************************
2025-10-08 12:15:08.448713 | controller |
2025-10-08 12:15:08.448836 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:15:08.448950 | controller | Wednesday 08 October 2025  12:15:08 +0000 (0:00:00.022)       0:00:00.022 *****
2025-10-08 12:15:09.308140 | controller | ok: [instance]
2025-10-08 12:15:09.308214 | controller |
2025-10-08 12:15:09.308322 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-10-08 12:15:09.308426 | controller | Wednesday 08 October 2025  12:15:09 +0000 (0:00:00.860)       0:00:00.882 *****
2025-10-08 12:15:09.326738 | controller | skipping: [instance]
2025-10-08 12:15:09.326849 | controller |
2025-10-08 12:15:09.326978 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-10-08 12:15:09.327103 | controller | Wednesday 08 October 2025  12:15:09 +0000 (0:00:00.018)       0:00:00.901 *****
2025-10-08 12:15:09.369297 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-10-08 12:15:09.369370 | controller |
2025-10-08 12:15:09.369480 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-10-08 12:15:09.369587 | controller | Wednesday 08 October 2025  12:15:09 +0000 (0:00:00.042)       0:00:00.943 *****
2025-10-08 12:15:09.654683 | controller | ok: [instance]
2025-10-08 12:15:09.654772 | controller |
2025-10-08 12:15:09.654910 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-10-08 12:15:09.655014 | controller | Wednesday 08 October 2025  12:15:09 +0000 (0:00:00.285)       0:00:01.229 *****
2025-10-08 12:15:09.973758 | controller | ok: [instance]
2025-10-08 12:15:09.973858 | controller |
2025-10-08 12:15:09.973977 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-10-08 12:15:09.974090 | controller | Wednesday 08 October 2025  12:15:09 +0000 (0:00:00.319)       0:00:01.548 *****
2025-10-08 12:15:10.679083 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-10-08 12:15:10.679168 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-10-08 12:15:10.679273 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-10-08 12:15:10.679370 | controller |
2025-10-08 12:15:10.679470 | controller | TASK [Deploy repo-setup] *******************************************************
2025-10-08 12:15:10.679575 | controller | Wednesday 08 October 2025  12:15:10 +0000 (0:00:00.705)       0:00:02.253 *****
2025-10-08 12:15:10.741694 | controller |
2025-10-08 12:15:10.741832 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-10-08 12:15:10.741984 | controller | Wednesday 08 October 2025  12:15:10 +0000 (0:00:00.062)       0:00:02.316 *****
2025-10-08 12:15:11.303768 | controller | changed: [instance] => (item=tmp)
2025-10-08 12:15:11.303889 | controller | changed: [instance] => (item=artifacts/repositories)
2025-10-08 12:15:11.303999 | controller | changed: [instance] => (item=venv/repo_setup)
2025-10-08 12:15:11.304094 | controller |
2025-10-08 12:15:11.304198 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-10-08 12:15:11.304292 | controller | Wednesday 08 October 2025  12:15:11 +0000 (0:00:00.562)       0:00:02.878 *****
2025-10-08 12:15:12.130631 | controller | ok: [instance]
2025-10-08 12:15:12.130944 | controller |
2025-10-08 12:15:12.130976 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-10-08 12:15:12.130986 | controller | Wednesday 08 October 2025  12:15:12 +0000 (0:00:00.826)       0:00:03.704 *****
2025-10-08 12:15:13.319319 | controller | changed: [instance]
2025-10-08 12:15:21.397304 | controller |
2025-10-08 12:15:21.397341 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-10-08 12:15:21.397352 | controller | Wednesday 08 October 2025  12:15:13 +0000 (0:00:01.188)       0:00:04.893 *****
2025-10-08 12:15:21.397362 | controller | changed: [instance]
2025-10-08 12:15:22.117865 | controller |
2025-10-08 12:15:22.117902 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-10-08 12:15:22.117911 | controller | Wednesday 08 October 2025  12:15:21 +0000 (0:00:08.077)       0:00:12.971 *****
2025-10-08 12:15:22.117921 | controller | changed: [instance]
2025-10-08 12:15:22.139644 | controller |
2025-10-08 12:15:22.139669 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-10-08 12:15:22.139677 | controller | Wednesday 08 October 2025  12:15:22 +0000 (0:00:00.720)       0:00:13.691 *****
2025-10-08 12:15:22.139687 | controller | skipping: [instance]
2025-10-08 12:15:23.008898 | controller |
2025-10-08 12:15:23.008931 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-10-08 12:15:23.008939 | controller | Wednesday 08 October 2025  12:15:22 +0000 (0:00:00.022)       0:00:13.713 *****
2025-10-08 12:15:23.008950 | controller | changed: [instance]
2025-10-08 12:15:23.047228 | controller |
2025-10-08 12:15:23.047262 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-10-08 12:15:23.047270 | controller | Wednesday 08 October 2025  12:15:23 +0000 (0:00:00.868)       0:00:14.582 *****
2025-10-08 12:15:23.047280 | controller | skipping: [instance]
2025-10-08 12:15:23.084903 | controller |
2025-10-08 12:15:23.084931 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-10-08 12:15:23.084940 | controller | Wednesday 08 October 2025  12:15:23 +0000 (0:00:00.038)       0:00:14.621 *****
2025-10-08 12:15:23.084949 | controller | skipping: [instance]
2025-10-08 12:15:23.085068 | controller |
2025-10-08 12:15:23.085084 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-10-08 12:15:23.085093 | controller | Wednesday 08 October 2025  12:15:23 +0000 (0:00:00.037)       0:00:14.658 *****
2025-10-08 12:15:23.121908 | controller | skipping: [instance]
2025-10-08 12:15:23.122074 | controller |
2025-10-08 12:15:23.122094 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-10-08 12:15:23.694935 | controller | Wednesday 08 October 2025  12:15:23 +0000 (0:00:00.037)       0:00:14.696 *****
2025-10-08 12:15:23.694991 | controller | changed: [instance]
2025-10-08 12:15:24.162864 | controller |
2025-10-08 12:15:24.162900 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-10-08 12:15:24.162909 | controller | Wednesday 08 October 2025  12:15:23 +0000 (0:00:00.572)       0:00:15.268 *****
2025-10-08 12:15:24.162919 | controller | changed: [instance]
2025-10-08 12:15:24.191208 | controller |
2025-10-08 12:15:24.191241 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-10-08 12:15:24.191250 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.468)       0:00:15.736 *****
2025-10-08 12:15:24.191261 | controller | skipping: [instance]
2025-10-08 12:15:24.219494 | controller |
2025-10-08 12:15:24.219529 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-10-08 12:15:24.219539 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:15.765 *****
2025-10-08 12:15:24.219550 | controller | skipping: [instance]
2025-10-08 12:15:24.248919 | controller |
2025-10-08 12:15:24.248953 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-10-08 12:15:24.248961 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:15.793 *****
2025-10-08 12:15:24.248975 | controller | skipping: [instance]
2025-10-08 12:15:24.287711 | controller |
2025-10-08 12:15:24.287754 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-10-08 12:15:24.287762 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.029)       0:00:15.823 *****
2025-10-08 12:15:24.287774 | controller | ok: [instance]
2025-10-08 12:15:24.287852 | controller |
2025-10-08 12:15:24.287991 | controller | TASK [repo_setup : Create download directory] **********************************
2025-10-08 12:15:24.288109 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.039)       0:00:15.862 *****
2025-10-08 12:15:24.315954 | controller | skipping: [instance]
2025-10-08 12:15:24.316099 | controller |
2025-10-08 12:15:24.316232 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-10-08 12:15:24.316357 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:15.890 *****
2025-10-08 12:15:24.344208 | controller | skipping: [instance]
2025-10-08 12:15:24.344351 | controller |
2025-10-08 12:15:24.344506 | controller | TASK [Download the RPM] ********************************************************
2025-10-08 12:15:24.344679 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:15.918 *****
2025-10-08 12:15:24.374573 | controller | skipping: [instance]
2025-10-08 12:15:24.374721 | controller |
2025-10-08 12:15:24.374882 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-10-08 12:15:24.375018 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.030)       0:00:15.948 *****
2025-10-08 12:15:24.403395 | controller | skipping: [instance]
2025-10-08 12:15:24.403537 | controller |
2025-10-08 12:15:24.403703 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-10-08 12:15:24.403844 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:15.977 *****
2025-10-08 12:15:24.432040 | controller | skipping: [instance]
2025-10-08 12:15:24.432216 | controller |
2025-10-08 12:15:24.432347 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-10-08 12:15:24.432467 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.028)       0:00:16.006 *****
2025-10-08 12:15:24.462153 | controller | skipping: [instance]
2025-10-08 12:15:24.462279 | controller |
2025-10-08 12:15:24.462412 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-10-08 12:15:24.462534 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.030)       0:00:16.036 *****
2025-10-08 12:15:24.489429 | controller | skipping: [instance]
2025-10-08 12:15:24.489592 | controller |
2025-10-08 12:15:24.489770 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-10-08 12:15:24.489944 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.027)       0:00:16.063 *****
2025-10-08 12:15:24.677868 | controller | ok: [instance]
2025-10-08 12:15:24.896341 | controller |
2025-10-08 12:15:24.896378 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-10-08 12:15:24.896387 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.187)       0:00:16.251 *****
2025-10-08 12:15:24.896398 | controller | changed: [instance]
2025-10-08 12:15:25.139194 | controller |
2025-10-08 12:15:25.139242 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-10-08 12:15:25.139251 | controller | Wednesday 08 October 2025  12:15:24 +0000 (0:00:00.218)       0:00:16.470 *****
2025-10-08 12:15:25.139265 | controller | changed: [instance]
2025-10-08 12:15:25.162763 | controller |
2025-10-08 12:15:25.162799 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-10-08 12:15:25.162823 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.242)       0:00:16.712 *****
2025-10-08 12:15:25.162838 | controller | skipping: [instance]
2025-10-08 12:15:25.185928 | controller |
2025-10-08 12:15:25.185964 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-10-08 12:15:25.185974 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.736 *****
2025-10-08 12:15:25.185986 | controller | skipping: [instance]
2025-10-08 12:15:25.186019 | controller |
2025-10-08 12:15:25.186298 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-10-08 12:15:25.209927 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.760 *****
2025-10-08 12:15:25.209984 | controller | skipping: [instance]
2025-10-08 12:15:25.233268 | controller |
2025-10-08 12:15:25.233308 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-10-08 12:15:25.233316 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.783 *****
2025-10-08 12:15:25.233327 | controller | skipping: [instance]
2025-10-08 12:15:25.256698 | controller |
2025-10-08 12:15:25.256735 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-10-08 12:15:25.256753 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.807 *****
2025-10-08 12:15:25.256765 | controller | skipping: [instance]
2025-10-08 12:15:25.279571 | controller |
2025-10-08 12:15:25.279598 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-10-08 12:15:25.279613 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.830 *****
2025-10-08 12:15:25.279643 | controller | skipping: [instance]
2025-10-08 12:15:25.296442 | controller |
2025-10-08 12:15:25.296471 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-10-08 12:15:25.296480 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.023)       0:00:16.853 *****
2025-10-08 12:15:25.296493 | controller | skipping: [instance]
2025-10-08 12:15:25.296697 | controller |
2025-10-08 12:15:25.296901 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-10-08 12:15:25.297052 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.017)       0:00:16.871 *****
2025-10-08 12:15:25.349419 | controller | skipping: [instance]
2025-10-08 12:15:25.349645 | controller |
2025-10-08 12:15:25.349862 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-10-08 12:15:25.350036 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.052)       0:00:16.923 *****
2025-10-08 12:15:25.366763 | controller | skipping: [instance]
2025-10-08 12:15:25.366990 | controller |
2025-10-08 12:15:25.367144 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-10-08 12:15:25.367297 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.017)       0:00:16.941 *****
2025-10-08 12:15:25.388086 | controller | skipping: [instance]
2025-10-08 12:15:25.388277 | controller |
2025-10-08 12:15:25.388451 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-10-08 12:15:25.388621 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.021)       0:00:16.962 *****
2025-10-08 12:15:25.419081 | controller | skipping: [instance]
2025-10-08 12:15:25.419251 | controller |
2025-10-08 12:15:25.419403 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-10-08 12:15:25.419550 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.030)       0:00:16.993 *****
2025-10-08 12:15:25.449699 | controller | skipping: [instance]
2025-10-08 12:15:25.449931 | controller |
2025-10-08 12:15:25.450125 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-10-08 12:15:25.450271 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.030)       0:00:17.024 *****
2025-10-08 12:15:25.479867 | controller | skipping: [instance]
2025-10-08 12:15:25.480035 | controller |
2025-10-08 12:15:25.480182 | controller | TASK [test_deps : Install additional packages] *********************************
2025-10-08 12:15:25.480330 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.030)       0:00:17.054 *****
2025-10-08 12:15:25.509990 | controller | skipping: [instance]
2025-10-08 12:15:25.510157 | controller |
2025-10-08 12:15:25.510304 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-10-08 12:15:25.510446 | controller | Wednesday 08 October 2025  12:15:25 +0000 (0:00:00.030)       0:00:17.084 *****
2025-10-08 12:16:09.203961 | controller | ok: [instance]
2025-10-08 12:16:09.204028 | controller |
2025-10-08 12:16:09.204055 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-10-08 12:16:09.204247 | controller | Wednesday 08 October 2025  12:16:09 +0000 (0:00:43.693)       0:01:00.778 *****
2025-10-08 12:16:10.488274 | controller | ok: [instance]
2025-10-08 12:16:14.353287 | controller |
2025-10-08 12:16:14.353329 | controller | TASK [test_deps : Install extra packages] **************************************
2025-10-08 12:16:14.353337 | controller | Wednesday 08 October 2025  12:16:10 +0000 (0:00:01.283)       0:01:02.061 *****
2025-10-08 12:16:14.353348 | controller | changed: [instance]
2025-10-08 12:16:14.353379 | controller |
2025-10-08 12:16:14.353644 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-10-08 12:16:14.573326 | controller | Wednesday 08 October 2025  12:16:14 +0000 (0:00:03.864)       0:01:05.926 *****
2025-10-08 12:16:14.573367 | controller | ok: [instance]
2025-10-08 12:16:14.787456 | controller |
2025-10-08 12:16:14.787494 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-10-08 12:16:14.787502 | controller | Wednesday 08 October 2025  12:16:14 +0000 (0:00:00.221)       0:01:06.147 *****
2025-10-08 12:16:14.787512 | controller | changed: [instance]
2025-10-08 12:16:14.997078 | controller |
2025-10-08 12:16:14.997120 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-10-08 12:16:14.997129 | controller | Wednesday 08 October 2025  12:16:14 +0000 (0:00:00.214)       0:01:06.361 *****
2025-10-08 12:16:14.997141 | controller | ok: [instance]
2025-10-08 12:16:15.030958 | controller |
2025-10-08 12:16:15.031001 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-10-08 12:16:15.031019 | controller | Wednesday 08 October 2025  12:16:14 +0000 (0:00:00.209)       0:01:06.570 *****
2025-10-08 12:16:15.031033 | controller | skipping: [instance]
2025-10-08 12:16:15.031066 | controller |
2025-10-08 12:16:15.031250 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-10-08 12:16:15.031298 | controller | Wednesday 08 October 2025  12:16:15 +0000 (0:00:00.034)       0:01:06.605 *****
2025-10-08 12:16:15.052910 | controller | skipping: [instance]
2025-10-08 12:16:15.053183 | controller |
2025-10-08 12:16:15.053233 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-10-08 12:16:15.075894 | controller | Wednesday 08 October 2025  12:16:15 +0000 (0:00:00.021)       0:01:06.626 *****
2025-10-08 12:16:15.075924 | controller | ok: [instance]
2025-10-08 12:16:15.075953 | controller |
2025-10-08 12:16:15.075960 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-10-08 12:16:15.075968 | controller | Wednesday 08 October 2025  12:16:15 +0000 (0:00:00.022)       0:01:06.649 *****
2025-10-08 12:16:15.108925 | controller | skipping: [instance]
2025-10-08 12:16:15.109226 | controller |
2025-10-08 12:16:15.109284 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-10-08 12:17:30.385345 | controller | Wednesday 08 October 2025  12:16:15 +0000 (0:00:00.033)       0:01:06.682 *****
2025-10-08 12:17:30.385384 | controller | changed: [instance]
2025-10-08 12:17:30.597381 | controller |
2025-10-08 12:17:30.597422 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-10-08 12:17:30.597431 | controller | Wednesday 08 October 2025  12:17:30 +0000 (0:01:15.276)       0:02:21.959 *****
2025-10-08 12:17:30.597442 | controller | changed: [instance]
2025-10-08 12:17:30.597466 | controller |
2025-10-08 12:17:30.597475 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-10-08 12:17:30.597590 | controller | Wednesday 08 October 2025  12:17:30 +0000 (0:00:00.212)       0:02:22.171 *****
2025-10-08 12:17:30.980860 | controller | changed: [instance]
2025-10-08 12:17:30.980913 | controller |
2025-10-08 12:17:30.981108 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-10-08 12:17:31.568661 | controller | Wednesday 08 October 2025  12:17:30 +0000 (0:00:00.383)       0:02:22.555 *****
2025-10-08 12:17:31.568701 | controller | changed: [instance]
2025-10-08 12:17:31.568722 | controller |
2025-10-08 12:17:31.568788 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-10-08 12:17:31.568934 | controller | Wednesday 08 October 2025  12:17:31 +0000 (0:00:00.587)       0:02:23.143 *****
2025-10-08 12:17:31.769832 | controller | ok: [instance]
2025-10-08 12:17:31.769906 | controller |
2025-10-08 12:17:31.769923 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-10-08 12:17:31.769935 | controller | Wednesday 08 October 2025  12:17:31 +0000 (0:00:00.200)       0:02:23.343 *****
2025-10-08 12:17:32.487178 | controller | ok: [instance]
2025-10-08 12:17:33.336678 | controller |
2025-10-08 12:17:33.336710 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-10-08 12:17:33.336719 | controller | Wednesday 08 October 2025  12:17:32 +0000 (0:00:00.717)       0:02:24.061 *****
2025-10-08 12:17:33.336729 | controller | changed: [instance]
2025-10-08 12:17:33.413982 | controller |
2025-10-08 12:17:33.414016 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-10-08 12:17:33.414025 | controller | Wednesday 08 October 2025  12:17:33 +0000 (0:00:00.849)       0:02:24.910 *****
2025-10-08 12:17:33.414036 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-10-08 12:17:33.414062 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-10-08 12:17:33.414075 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-10-08 12:17:33.414081 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-10-08 12:17:33.414087 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-10-08 12:17:33.414093 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-10-08 12:17:33.414100 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-10-08 12:17:33.414128 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-10-08 12:17:33.414141 | controller |
2025-10-08 12:17:33.414220 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-10-08 12:17:33.414372 | controller | Wednesday 08 October 2025  12:17:33 +0000 (0:00:00.077)       0:02:24.987 *****
2025-10-08 12:17:33.748541 | controller | changed: [instance]
2025-10-08 12:17:33.748651 | controller |
2025-10-08 12:17:33.748663 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-10-08 12:17:33.748686 | controller | Wednesday 08 October 2025  12:17:33 +0000 (0:00:00.335)       0:02:25.322 *****
2025-10-08 12:17:34.082180 | controller | changed: [instance]
2025-10-08 12:17:34.082503 | controller |
2025-10-08 12:17:34.421265 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-10-08 12:17:34.421296 | controller | Wednesday 08 October 2025  12:17:34 +0000 (0:00:00.333)       0:02:25.656 *****
2025-10-08 12:17:34.421308 | controller | changed: [instance]
2025-10-08 12:17:34.760635 | controller |
2025-10-08 12:17:34.760666 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-10-08 12:17:34.760673 | controller | Wednesday 08 October 2025  12:17:34 +0000 (0:00:00.338)       0:02:25.995 *****
2025-10-08 12:17:34.760690 | controller | changed: [instance]
2025-10-08 12:17:35.097646 | controller |
2025-10-08 12:17:35.097677 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-10-08 12:17:35.097686 | controller | Wednesday 08 October 2025  12:17:34 +0000 (0:00:00.339)       0:02:26.334 *****
2025-10-08 12:17:35.097696 | controller | changed: [instance]
2025-10-08 12:17:35.428570 | controller |
2025-10-08 12:17:35.428602 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-10-08 12:17:35.428610 | controller | Wednesday 08 October 2025  12:17:35 +0000 (0:00:00.337)       0:02:26.671 *****
2025-10-08 12:17:35.428621 | controller | changed: [instance]
2025-10-08 12:17:35.774414 | controller |
2025-10-08 12:17:35.774447 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-10-08 12:17:35.774455 | controller | Wednesday 08 October 2025  12:17:35 +0000 (0:00:00.330)       0:02:27.002 *****
2025-10-08 12:17:35.774465 | controller | changed: [instance]
2025-10-08 12:17:36.122971 | controller |
2025-10-08 12:17:36.123007 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-10-08 12:17:36.123015 | controller | Wednesday 08 October 2025  12:17:35 +0000 (0:00:00.345)       0:02:27.348 *****
2025-10-08 12:17:36.123025 | controller | changed: [instance]
2025-10-08 12:17:36.123427 | controller |
2025-10-08 12:17:36.477110 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-10-08 12:17:36.477142 | controller | Wednesday 08 October 2025  12:17:36 +0000 (0:00:00.348)       0:02:27.697 *****
2025-10-08 12:17:36.477155 | controller | changed: [instance]
2025-10-08 12:17:36.861551 | controller |
2025-10-08 12:17:36.861582 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-10-08 12:17:36.861591 | controller | Wednesday 08 October 2025  12:17:36 +0000 (0:00:00.353)       0:02:28.050 *****
2025-10-08 12:17:36.861601 | controller | changed: [instance]
2025-10-08 12:17:37.219920 | controller |
2025-10-08 12:17:37.219978 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-10-08 12:17:37.219988 | controller | Wednesday 08 October 2025  12:17:36 +0000 (0:00:00.385)       0:02:28.435 *****
2025-10-08 12:17:37.219999 | controller | changed: [instance]
2025-10-08 12:17:37.564925 | controller |
2025-10-08 12:17:37.564989 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-10-08 12:17:37.565001 | controller | Wednesday 08 October 2025  12:17:37 +0000 (0:00:00.358)       0:02:28.794 *****
2025-10-08 12:17:37.565014 | controller | changed: [instance]
2025-10-08 12:17:37.565249 | controller |
2025-10-08 12:17:37.914936 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-10-08 12:17:37.914986 | controller | Wednesday 08 October 2025  12:17:37 +0000 (0:00:00.345)       0:02:29.139 *****
2025-10-08 12:17:37.914998 | controller | changed: [instance]
2025-10-08 12:17:38.250510 | controller |
2025-10-08 12:17:38.250544 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-10-08 12:17:38.250553 | controller | Wednesday 08 October 2025  12:17:37 +0000 (0:00:00.349)       0:02:29.489 *****
2025-10-08 12:17:38.250564 | controller | changed: [instance]
2025-10-08 12:17:38.588884 | controller |
2025-10-08 12:17:38.588915 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-10-08 12:17:38.588923 | controller | Wednesday 08 October 2025  12:17:38 +0000 (0:00:00.335)       0:02:29.824 *****
2025-10-08 12:17:38.588933 | controller | changed: [instance]
2025-10-08 12:17:38.588972 | controller |
2025-10-08 12:17:38.589162 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-10-08 12:17:38.923705 | controller | Wednesday 08 October 2025  12:17:38 +0000 (0:00:00.338)       0:02:30.163 *****
2025-10-08 12:17:38.923740 | controller | changed: [instance]
2025-10-08 12:17:39.265717 | controller |
2025-10-08 12:17:39.265753 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-10-08 12:17:39.265761 | controller | Wednesday 08 October 2025  12:17:38 +0000 (0:00:00.334)       0:02:30.497 *****
2025-10-08 12:17:39.265772 | controller | changed: [instance]
2025-10-08 12:17:39.609011 | controller |
2025-10-08 12:17:39.609045 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-10-08 12:17:39.609053 | controller | Wednesday 08 October 2025  12:17:39 +0000 (0:00:00.341)       0:02:30.839 *****
2025-10-08 12:17:39.609063 | controller | changed: [instance]
2025-10-08 12:17:39.955703 | controller |
2025-10-08 12:17:39.955741 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-10-08 12:17:39.955749 | controller | Wednesday 08 October 2025  12:17:39 +0000 (0:00:00.343)       0:02:31.183 *****
2025-10-08 12:17:39.955759 | controller | changed: [instance]
2025-10-08 12:17:40.315320 | controller |
2025-10-08 12:17:40.315350 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-10-08 12:17:40.315363 | controller | Wednesday 08 October 2025  12:17:39 +0000 (0:00:00.346)       0:02:31.529 *****
2025-10-08 12:17:40.315374 | controller | changed: [instance]
2025-10-08 12:17:40.643856 | controller |
2025-10-08 12:17:40.643886 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-10-08 12:17:40.643895 | controller | Wednesday 08 October 2025  12:17:40 +0000 (0:00:00.359)       0:02:31.889 *****
2025-10-08 12:17:40.643905 | controller | changed: [instance]
2025-10-08 12:17:40.970034 | controller |
2025-10-08 12:17:40.970070 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-10-08 12:17:40.970078 | controller | Wednesday 08 October 2025  12:17:40 +0000 (0:00:00.328)       0:02:32.218 *****
2025-10-08 12:17:40.970088 | controller | changed: [instance]
2025-10-08 12:17:41.334431 | controller |
2025-10-08 12:17:41.334465 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-10-08 12:17:41.334474 | controller | Wednesday 08 October 2025  12:17:40 +0000 (0:00:00.326)       0:02:32.544 *****
2025-10-08 12:17:41.334484 | controller | changed: [instance]
2025-10-08 12:17:41.695894 | controller |
2025-10-08 12:17:41.695925 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-10-08 12:17:41.695933 | controller | Wednesday 08 October 2025  12:17:41 +0000 (0:00:00.364)       0:02:32.908 *****
2025-10-08 12:17:41.695950 | controller | changed: [instance]
2025-10-08 12:17:41.696203 | controller |
2025-10-08 12:17:41.696218 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-10-08 12:17:41.717954 | controller | Wednesday 08 October 2025  12:17:41 +0000 (0:00:00.361)       0:02:33.270 *****
2025-10-08 12:17:41.718013 | controller | skipping: [instance]
2025-10-08 12:17:41.718102 | controller |
2025-10-08 12:17:41.718137 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-10-08 12:17:41.718149 | controller | Wednesday 08 October 2025  12:17:41 +0000 (0:00:00.021)       0:02:33.291 *****
2025-10-08 12:17:41.992904 | controller | ok: [instance]
2025-10-08 12:17:41.992937 | controller |
2025-10-08 12:17:41.992945 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-10-08 12:17:41.992954 | controller | Wednesday 08 October 2025  12:17:41 +0000 (0:00:00.275)       0:02:33.566 *****
2025-10-08 12:17:42.420275 | controller | changed: [instance]
2025-10-08 12:17:42.712683 | controller |
2025-10-08 12:17:42.712717 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-10-08 12:17:42.712725 | controller | Wednesday 08 October 2025  12:17:42 +0000 (0:00:00.427)       0:02:33.994 *****
2025-10-08 12:17:42.712735 | controller | changed: [instance]
2025-10-08 12:17:42.993560 | controller |
2025-10-08 12:17:42.993595 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-10-08 12:17:42.993603 | controller | Wednesday 08 October 2025  12:17:42 +0000 (0:00:00.292)       0:02:34.286 *****
2025-10-08 12:17:42.993613 | controller | [WARNING]: Reset is not implemented for this connection
2025-10-08 12:17:43.006060 | controller | changed: [instance]
2025-10-08 12:17:43.006120 | controller |
2025-10-08 12:17:43.006129 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-10-08 12:17:43.006136 | controller | Wednesday 08 October 2025  12:17:42 +0000 (0:00:00.276)       0:02:34.562 *****
2025-10-08 12:17:43.006142 | controller |
2025-10-08 12:17:43.006147 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-10-08 12:17:43.006155 | controller | Wednesday 08 October 2025  12:17:43 +0000 (0:00:00.016)       0:02:34.579 *****
2025-10-08 12:17:44.666999 | controller | changed: [instance]
2025-10-08 12:17:44.694979 | controller |
2025-10-08 12:17:44.695039 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-10-08 12:17:44.695050 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:01.661)       0:02:36.240 *****
2025-10-08 12:17:44.695064 | controller | ok: [instance]
2025-10-08 12:17:44.695097 | controller |
2025-10-08 12:17:44.695106 | controller | TASK [Load networking definition] **********************************************
2025-10-08 12:17:44.717287 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:00.028)       0:02:36.269 *****
2025-10-08 12:17:44.717338 | controller | ok: [instance]
2025-10-08 12:17:44.749639 | controller |
2025-10-08 12:17:44.749682 | controller | TASK [libvirt_manager : Import layout generator if needed] *********************
2025-10-08 12:17:44.749691 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:00.022)       0:02:36.291 *****
2025-10-08 12:17:44.749702 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_layout.yml for instance
2025-10-08 12:17:44.780776 | controller |
2025-10-08 12:17:44.780829 | controller | TASK [libvirt_manager : Chose right parameter for layout definition] ***********
2025-10-08 12:17:44.780840 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:00.032)       0:02:36.323 *****
2025-10-08 12:17:44.780859 | controller | ok: [instance]
2025-10-08 12:17:44.836943 | controller |
2025-10-08 12:17:44.837015 | controller | TASK [libvirt_manager : Patch the layout if needed] ****************************
2025-10-08 12:17:44.837024 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:00.031)       0:02:36.354 *****
2025-10-08 12:17:44.837036 | controller | skipping: [instance]
2025-10-08 12:17:45.269572 | controller |
2025-10-08 12:17:45.269608 | controller | TASK [libvirt_manager : Enable forwarding in the libvirt zone] *****************
2025-10-08 12:17:45.269616 | controller | Wednesday 08 October 2025  12:17:44 +0000 (0:00:00.056)       0:02:36.410 *****
2025-10-08 12:17:45.269635 | controller | changed: [instance]
2025-10-08 12:17:45.269655 | controller |
2025-10-08 12:17:45.269918 | controller | TASK [libvirt_manager : Enable masquerading for public traffic] ****************
2025-10-08 12:17:45.780505 | controller | Wednesday 08 October 2025  12:17:45 +0000 (0:00:00.432)       0:02:36.843 *****
2025-10-08 12:17:45.780558 | controller | changed: [instance]
2025-10-08 12:17:45.780579 | controller |
2025-10-08 12:17:45.781174 | controller | TASK [libvirt_manager : Ensure firewalld is restarts] **************************
2025-10-08 12:17:46.529938 | controller | Wednesday 08 October 2025  12:17:45 +0000 (0:00:00.502)       0:02:37.346 *****
2025-10-08 12:17:46.529995 | controller |
2025-10-08 12:17:46.530004 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-10-08 12:17:46.530010 | controller | Wednesday 08 October 2025  12:17:45 +0000 (0:00:00.008)       0:02:37.354 *****
2025-10-08 12:17:46.530021 | controller | changed: [instance]
2025-10-08 12:17:46.559386 | controller |
2025-10-08 12:17:46.559417 | controller | TASK [Deploy virtualbmc] *******************************************************
2025-10-08 12:17:46.559425 | controller | Wednesday 08 October 2025  12:17:46 +0000 (0:00:00.749)       0:02:38.104 *****
2025-10-08 12:17:46.559435 | controller | skipping: [instance]
2025-10-08 12:17:46.589122 | controller |
2025-10-08 12:17:46.589154 | controller | TASK [libvirt_manager : Let the project know we have vbmc available] ***********
2025-10-08 12:17:46.589161 | controller | Wednesday 08 October 2025  12:17:46 +0000 (0:00:00.029)       0:02:38.133 *****
2025-10-08 12:17:46.589172 | controller | skipping: [instance]
2025-10-08 12:17:47.167895 | controller |
2025-10-08 12:17:47.167931 | controller | TASK [libvirt_manager : Create needed workload directory] **********************
2025-10-08 12:17:47.167939 | controller | Wednesday 08 October 2025  12:17:46 +0000 (0:00:00.029)       0:02:38.163 *****
2025-10-08 12:17:47.167949 | controller | changed: [instance] => (item=workload)
2025-10-08 12:17:47.168039 | controller | changed: [instance] => (item=reproducer-inventory)
2025-10-08 12:17:47.168051 | controller | changed: [instance] => (item=volumes)
2025-10-08 12:17:47.168064 | controller |
2025-10-08 12:17:47.168070 | controller | TASK [libvirt_manager : Allow QEMU on workload directory] **********************
2025-10-08 12:17:47.168078 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.578)       0:02:38.741 *****
2025-10-08 12:17:47.596874 | controller | changed: [instance] => (item=workload)
2025-10-08 12:17:47.669369 | controller | changed: [instance] => (item=volumes)
2025-10-08 12:17:47.669402 | controller |
2025-10-08 12:17:47.669410 | controller | TASK [libvirt_manager : Generate networking data] ******************************
2025-10-08 12:17:47.669417 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.429)       0:02:39.170 *****
2025-10-08 12:17:47.669427 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_networking_data.yml for instance
2025-10-08 12:17:47.686489 | controller |
2025-10-08 12:17:47.686522 | controller | TASK [libvirt_manager : Ensure fact is existing, and empty] ********************
2025-10-08 12:17:47.686530 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.072)       0:02:39.243 *****
2025-10-08 12:17:47.686541 | controller | ok: [instance]
2025-10-08 12:17:47.883278 | controller |
2025-10-08 12:17:47.883313 | controller | TASK [libvirt_manager : Check if we get an existing interfaces-info.yml] *******
2025-10-08 12:17:47.883322 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.017)       0:02:39.260 *****
2025-10-08 12:17:47.883332 | controller | ok: [instance]
2025-10-08 12:17:47.911392 | controller |
2025-10-08 12:17:47.911426 | controller | TASK [libvirt_manager : Load file if exists] ***********************************
2025-10-08 12:17:47.911434 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.196)       0:02:39.457 *****
2025-10-08 12:17:47.911445 | controller | skipping: [instance]
2025-10-08 12:17:47.940315 | controller |
2025-10-08 12:17:47.940349 | controller | TASK [libvirt_manager : Update fact with existing content] *********************
2025-10-08 12:17:47.940357 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.028)       0:02:39.485 *****
2025-10-08 12:17:47.940368 | controller | skipping: [instance]
2025-10-08 12:17:47.990663 | controller |
2025-10-08 12:17:47.990704 | controller | TASK [libvirt_manager : Generate VM list] **************************************
2025-10-08 12:17:47.990713 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.028)       0:02:39.514 *****
2025-10-08 12:17:47.990734 | controller | ok: [instance]
2025-10-08 12:17:48.065317 | controller |
2025-10-08 12:17:48.065350 | controller | TASK [libvirt_manager : Generate/update mapping all nodes] *********************
2025-10-08 12:17:48.065365 | controller | Wednesday 08 October 2025  12:17:47 +0000 (0:00:00.050)       0:02:39.564 *****
2025-10-08 12:17:48.065376 | controller | ok: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-08 12:17:48.065525 | controller |
2025-10-08 12:17:48.065675 | controller | TASK [libvirt_manager : Append baremetal nodes if needed] **********************
2025-10-08 12:17:48.065847 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.075)       0:02:39.639 *****
2025-10-08 12:17:48.098933 | controller | skipping: [instance]
2025-10-08 12:17:48.099009 | controller |
2025-10-08 12:17:48.099021 | controller | TASK [libvirt_manager : Dump MAC mapping] **************************************
2025-10-08 12:17:48.099130 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.033)       0:02:39.673 *****
2025-10-08 12:17:48.443718 | controller | changed: [instance]
2025-10-08 12:17:48.504152 | controller |
2025-10-08 12:17:48.504187 | controller | TASK [libvirt_manager : Inject all VMs in the inventory] ***********************
2025-10-08 12:17:48.504195 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.344)       0:02:40.017 *****
2025-10-08 12:17:48.504205 | controller | changed: [instance] => (item=Adding compute-0 to computes)
2025-10-08 12:17:48.526953 | controller |
2025-10-08 12:17:48.526998 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-10-08 12:17:48.527007 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.060)       0:02:40.078 *****
2025-10-08 12:17:48.527017 | controller | skipping: [instance]
2025-10-08 12:17:48.549312 | controller |
2025-10-08 12:17:48.549342 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-10-08 12:17:48.549351 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.022)       0:02:40.101 *****
2025-10-08 12:17:48.549361 | controller | skipping: [instance]
2025-10-08 12:17:48.571889 | controller |
2025-10-08 12:17:48.571921 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-10-08 12:17:48.571929 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.022)       0:02:40.123 *****
2025-10-08 12:17:48.571939 | controller | skipping: [instance]
2025-10-08 12:17:48.595924 | controller |
2025-10-08 12:17:48.595979 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-10-08 12:17:48.595990 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.022)       0:02:40.146 *****
2025-10-08 12:17:48.596002 | controller | skipping: [instance]
2025-10-08 12:17:48.613882 | controller |
2025-10-08 12:17:48.613920 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-10-08 12:17:48.613930 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.024)       0:02:40.170 *****
2025-10-08 12:17:48.613943 | controller | ok: [instance]
2025-10-08 12:17:48.614026 | controller |
2025-10-08 12:17:48.614042 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-10-08 12:17:48.614052 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.017)       0:02:40.188 *****
2025-10-08 12:17:48.708918 | 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, 'tools': {'multus': {'ranges': [{'start': 30, 'end': 39}]}, 'netconfig': {'ranges': [{'start': '192.168.122.40', 'end': '192.168.122.49'}]}, 'metallb': {'ranges': [{'start': '192.168.122.80', 'end': '192.168.122.90'}]}}}, 'internalapi': {'network': '172.17.0.0/24', 'gateway': '172.17.0.1', 'vlan': 20, 'mtu': 1496, 'tools': {'metallb': {'ranges': [{'start': '172.17.0.90', 'end': '172.17.0.100'}]}, 'netconfig': {'ranges': [{'start': '172.17.0.40', 'end': '172.17.0.49'}]}, 'multus': {'ranges': [{'start': 50, 'end': 59}]}}}, 'storage': {'network': '172.18.0.0/24', 'vlan': 21, 'mtu': 1496, 'tools': {'netconfig': {'ranges': [{'start': '172.18.0.40', 'end': '172.18.0.49'}]}}}, 'tenant': {'network': '172.19.0.0/24', 'gateway-v4': '172.19.0.1', 'search-domain': 'tenant.example.local', 'dns-v4': ['8.8.8.8', '172.19.0.1'], 'tools': {'netconfig': {'ranges': [{'start': '172.19.0.40', 'end': '172.19.0.49'}]}}, 'vlan': 22, 'mtu': 1496}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}, 'internalapi': {}, 'tenant': {}, 'storage': {}}}, 'sl-computes': {'network-template': {'range': {'start': 16, 'length': 2}}, 'networks': {'ctlplane': {}, 'internalapi': {}, 'tenant': {}, 'storage': {}}}, 'baremetals': {'networks': {'ctlplane': {'range': '192.168.122.20-192.168.122.24'}, 'internalapi': {'range': '20-24'}, 'tenant': {'range': {'start': 20, 'length': 5}}, 'storage': {'range': {'start': 20, 'length': 5}}}}}})
2025-10-08 12:17:48.708976 | controller |
2025-10-08 12:17:48.708987 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-10-08 12:17:48.708998 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.094)       0:02:40.283 *****
2025-10-08 12:17:48.726305 | controller | skipping: [instance]
2025-10-08 12:17:48.967200 | controller |
2025-10-08 12:17:48.967236 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-10-08 12:17:48.967245 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.017)       0:02:40.300 *****
2025-10-08 12:17:48.967255 | controller | changed: [instance]
2025-10-08 12:17:49.447568 | controller |
2025-10-08 12:17:49.447602 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-10-08 12:17:49.447611 | controller | Wednesday 08 October 2025  12:17:48 +0000 (0:00:00.240)       0:02:40.541 *****
2025-10-08 12:17:49.447621 | controller | changed: [instance]
2025-10-08 12:17:49.497595 | controller |
2025-10-08 12:17:49.497628 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-10-08 12:17:49.497637 | controller | Wednesday 08 October 2025  12:17:49 +0000 (0:00:00.480)       0:02:41.021 *****
2025-10-08 12:17:49.497647 | controller | ok: [instance]
2025-10-08 12:17:49.524901 | controller |
2025-10-08 12:17:49.524943 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-10-08 12:17:49.524952 | controller | Wednesday 08 October 2025  12:17:49 +0000 (0:00:00.050)       0:02:41.071 *****
2025-10-08 12:17:49.524984 | controller | ok: [instance]
2025-10-08 12:17:49.954670 | controller |
2025-10-08 12:17:49.954706 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-10-08 12:17:49.954715 | controller | Wednesday 08 October 2025  12:17:49 +0000 (0:00:00.027)       0:02:41.098 *****
2025-10-08 12:17:49.954735 | controller | changed: [instance]
2025-10-08 12:17:50.027040 | controller |
2025-10-08 12:17:50.027093 | controller | TASK [libvirt_manager : Manage networks if needed] *****************************
2025-10-08 12:17:50.027102 | controller | Wednesday 08 October 2025  12:17:49 +0000 (0:00:00.429)       0:02:41.528 *****
2025-10-08 12:17:50.027113 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks.yml for instance
2025-10-08 12:17:50.069006 | controller |
2025-10-08 12:17:50.069042 | controller | TASK [libvirt_manager : Define the localized variables for performing the tasks here.] ***
2025-10-08 12:17:50.069051 | controller | Wednesday 08 October 2025  12:17:50 +0000 (0:00:00.072)       0:02:41.600 *****
2025-10-08 12:17:50.069062 | controller | ok: [instance] => (item=public)
2025-10-08 12:17:50.841711 | controller |
2025-10-08 12:17:50.841751 | controller | TASK [libvirt_manager : Ensure networks are defined] ***************************
2025-10-08 12:17:50.841760 | controller | Wednesday 08 October 2025  12:17:50 +0000 (0:00:00.041)       0:02:41.642 *****
2025-10-08 12:17:50.841771 | controller | changed: [instance] => (item=cifmw-public)
2025-10-08 12:17:51.184569 | controller |
2025-10-08 12:17:51.184606 | controller | TASK [libvirt_manager : Ensure networks are created/started] *******************
2025-10-08 12:17:51.184615 | controller | Wednesday 08 October 2025  12:17:50 +0000 (0:00:00.772)       0:02:42.415 *****
2025-10-08 12:17:51.184625 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:17:51.420907 | controller |
2025-10-08 12:17:51.420938 | controller | TASK [libvirt_manager : Ensure networks are active] ****************************
2025-10-08 12:17:51.420946 | controller | Wednesday 08 October 2025  12:17:51 +0000 (0:00:00.342)       0:02:42.758 *****
2025-10-08 12:17:51.420977 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:17:51.421304 | controller |
2025-10-08 12:17:51.641349 | controller | TASK [libvirt_manager : Ensure networks enabled to autostart] ******************
2025-10-08 12:17:51.641378 | controller | Wednesday 08 October 2025  12:17:51 +0000 (0:00:00.236)       0:02:42.995 *****
2025-10-08 12:17:51.641390 | controller | changed: [instance] => (item=cifmw-public)
2025-10-08 12:17:51.690973 | controller |
2025-10-08 12:17:51.691016 | controller | TASK [libvirt_manager : Add a dummy interface to bridges if required] **********
2025-10-08 12:17:51.691024 | controller | Wednesday 08 October 2025  12:17:51 +0000 (0:00:00.220)       0:02:43.215 *****
2025-10-08 12:17:51.691035 | 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-08 12:17:51.691062 | controller |
2025-10-08 12:17:51.691337 | controller | TASK [libvirt_manager : Fetch present bridge interfaces] ***********************
2025-10-08 12:17:51.874930 | controller | Wednesday 08 October 2025  12:17:51 +0000 (0:00:00.049)       0:02:43.265 *****
2025-10-08 12:17:51.874984 | controller | ok: [instance]
2025-10-08 12:17:52.079293 | controller |
2025-10-08 12:17:52.079323 | controller | TASK [libvirt_manager : Fetch bridges ports link info] *************************
2025-10-08 12:17:52.079332 | controller | Wednesday 08 October 2025  12:17:51 +0000 (0:00:00.183)       0:02:43.449 *****
2025-10-08 12:17:52.079342 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:17:52.147330 | controller |
2025-10-08 12:17:52.147366 | controller | TASK [Create dummy interfaces to ensure bridges are UP] ************************
2025-10-08 12:17:52.147375 | controller | Wednesday 08 October 2025  12:17:52 +0000 (0:00:00.204)       0:02:43.653 *****
2025-10-08 12:17:52.147385 | controller |
2025-10-08 12:17:52.181616 | controller | TASK [ci_nmstate : Ensure we have needed facts] ********************************
2025-10-08 12:17:52.181643 | controller | Wednesday 08 October 2025  12:17:52 +0000 (0:00:00.067)       0:02:43.721 *****
2025-10-08 12:17:52.181654 | controller | skipping: [instance]
2025-10-08 12:18:03.135336 | controller |
2025-10-08 12:18:03.135379 | controller | TASK [ci_nmstate : Install required packages on instance] **********************
2025-10-08 12:18:03.135387 | controller | Wednesday 08 October 2025  12:17:52 +0000 (0:00:00.034)       0:02:43.755 *****
2025-10-08 12:18:03.135397 | controller | changed: [instance]
2025-10-08 12:18:03.345877 | controller |
2025-10-08 12:18:03.345915 | controller | TASK [ci_nmstate : Create the target NMstate dump directory] *******************
2025-10-08 12:18:03.345923 | controller | Wednesday 08 October 2025  12:18:03 +0000 (0:00:10.953)       0:02:54.709 *****
2025-10-08 12:18:03.345933 | controller | changed: [instance]
2025-10-08 12:18:03.722774 | controller |
2025-10-08 12:18:03.722822 | controller | TASK [ci_nmstate : Save nmstate state for instance] ****************************
2025-10-08 12:18:03.722834 | controller | Wednesday 08 October 2025  12:18:03 +0000 (0:00:00.210)       0:02:54.919 *****
2025-10-08 12:18:03.722845 | controller | changed: [instance]
2025-10-08 12:18:05.469744 | controller |
2025-10-08 12:18:05.469775 | controller | TASK [ci_nmstate : Apply the desidered state on instance] **********************
2025-10-08 12:18:05.469783 | controller | Wednesday 08 October 2025  12:18:03 +0000 (0:00:00.377)       0:02:55.296 *****
2025-10-08 12:18:05.469793 | controller | changed: [instance]
2025-10-08 12:18:05.832530 | controller |
2025-10-08 12:18:05.832562 | controller | TASK [ci_nmstate : Save nmstate debugging data for instance] *******************
2025-10-08 12:18:05.832576 | controller | Wednesday 08 October 2025  12:18:05 +0000 (0:00:01.746)       0:02:57.043 *****
2025-10-08 12:18:05.832587 | controller | changed: [instance]
2025-10-08 12:18:05.862586 | controller |
2025-10-08 12:18:05.862616 | controller | TASK [Create extra network configuration] **************************************
2025-10-08 12:18:05.862625 | controller | Wednesday 08 October 2025  12:18:05 +0000 (0:00:00.362)       0:02:57.406 *****
2025-10-08 12:18:05.862635 | controller | skipping: [instance]
2025-10-08 12:18:05.890594 | controller |
2025-10-08 12:18:05.890620 | controller | TASK [libvirt_manager : Ensure extra networks is in correct zone] **************
2025-10-08 12:18:05.890628 | controller | Wednesday 08 October 2025  12:18:05 +0000 (0:00:00.029)       0:02:57.436 *****
2025-10-08 12:18:05.890638 | controller | skipping: [instance]
2025-10-08 12:18:06.303899 | controller |
2025-10-08 12:18:06.303942 | controller | TASK [libvirt_manager : Refresh networking facts on host] **********************
2025-10-08 12:18:06.303951 | controller | Wednesday 08 October 2025  12:18:05 +0000 (0:00:00.028)       0:02:57.464 *****
2025-10-08 12:18:06.303978 | controller | ok: [instance]
2025-10-08 12:18:06.422935 | controller |
2025-10-08 12:18:06.422987 | controller | TASK [libvirt_manager : Build needed network/dnsmasq related content] **********
2025-10-08 12:18:06.422998 | controller | Wednesday 08 October 2025  12:18:06 +0000 (0:00:00.413)       0:02:57.877 *****
2025-10-08 12:18:06.423010 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:18:06.423040 | controller |
2025-10-08 12:18:06.423207 | controller | TASK [dnsmasq : Install needed packages] ***************************************
2025-10-08 12:18:07.647655 | controller | Wednesday 08 October 2025  12:18:06 +0000 (0:00:00.119)       0:02:57.997 *****
2025-10-08 12:18:07.647692 | controller | ok: [instance]
2025-10-08 12:18:11.236629 | controller |
2025-10-08 12:18:11.236663 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ******
2025-10-08 12:18:11.236671 | controller | Wednesday 08 October 2025  12:18:07 +0000 (0:00:01.224)       0:02:59.221 *****
2025-10-08 12:18:11.236682 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'})
2025-10-08 12:18:11.473461 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'})
2025-10-08 12:18:11.473492 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'})
2025-10-08 12:18:11.473500 | controller |
2025-10-08 12:18:11.473507 | controller | TASK [dnsmasq : Manage configuration directory] ********************************
2025-10-08 12:18:11.473512 | controller | Wednesday 08 October 2025  12:18:11 +0000 (0:00:03.588)       0:03:02.810 *****
2025-10-08 12:18:11.473522 | controller | changed: [instance]
2025-10-08 12:18:11.844666 | controller |
2025-10-08 12:18:11.844697 | controller | TASK [dnsmasq : Manage systemd unit file] **************************************
2025-10-08 12:18:11.844706 | controller | Wednesday 08 October 2025  12:18:11 +0000 (0:00:00.237)       0:03:03.047 *****
2025-10-08 12:18:11.844715 | controller | changed: [instance]
2025-10-08 12:18:12.268007 | controller |
2025-10-08 12:18:12.268039 | controller | TASK [dnsmasq : Manage base configuration file] ********************************
2025-10-08 12:18:12.268047 | controller | Wednesday 08 October 2025  12:18:11 +0000 (0:00:00.371)       0:03:03.418 *****
2025-10-08 12:18:12.268057 | controller | changed: [instance]
2025-10-08 12:18:12.298335 | controller |
2025-10-08 12:18:12.298368 | controller | TASK [dnsmasq : Render listener configuration] *********************************
2025-10-08 12:18:12.298377 | controller | Wednesday 08 October 2025  12:18:12 +0000 (0:00:00.423)       0:03:03.841 *****
2025-10-08 12:18:12.298389 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance
2025-10-08 12:18:12.711400 | controller |
2025-10-08 12:18:12.711437 | controller | TASK [dnsmasq : Create listener configuration file] ****************************
2025-10-08 12:18:12.711446 | controller | Wednesday 08 October 2025  12:18:12 +0000 (0:00:00.030)       0:03:03.872 *****
2025-10-08 12:18:12.711457 | controller | changed: [instance]
2025-10-08 12:18:12.731628 | controller |
2025-10-08 12:18:12.731664 | controller | TASK [dnsmasq : Remove listener configuration file] ****************************
2025-10-08 12:18:12.731672 | controller | Wednesday 08 October 2025  12:18:12 +0000 (0:00:00.412)       0:03:04.285 *****
2025-10-08 12:18:12.731682 | controller | skipping: [instance]
2025-10-08 12:18:12.762619 | controller |
2025-10-08 12:18:12.762646 | controller | TASK [dnsmasq : Render dns configuration] **************************************
2025-10-08 12:18:12.762654 | controller | Wednesday 08 October 2025  12:18:12 +0000 (0:00:00.020)       0:03:04.305 *****
2025-10-08 12:18:12.762665 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance
2025-10-08 12:18:13.144951 | controller |
2025-10-08 12:18:13.144996 | controller | TASK [dnsmasq : Create dns configuration file] *********************************
2025-10-08 12:18:13.145004 | controller | Wednesday 08 October 2025  12:18:12 +0000 (0:00:00.031)       0:03:04.336 *****
2025-10-08 12:18:13.145014 | controller | changed: [instance]
2025-10-08 12:18:13.145036 | controller |
2025-10-08 12:18:13.145052 | controller | TASK [dnsmasq : Remove dns configuration file] *********************************
2025-10-08 12:18:13.145145 | controller | Wednesday 08 October 2025  12:18:13 +0000 (0:00:00.382)       0:03:04.719 *****
2025-10-08 12:18:13.163777 | controller | skipping: [instance]
2025-10-08 12:18:13.377528 | controller |
2025-10-08 12:18:13.377560 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] ***
2025-10-08 12:18:13.377568 | controller | Wednesday 08 October 2025  12:18:13 +0000 (0:00:00.018)       0:03:04.737 *****
2025-10-08 12:18:13.377579 | controller | ok: [instance] => (item=127.0.0.2)
2025-10-08 12:18:14.134355 | controller |
2025-10-08 12:18:14.134394 | controller | TASK [dnsmasq : Enable and start service] **************************************
2025-10-08 12:18:14.134403 | controller | Wednesday 08 October 2025  12:18:13 +0000 (0:00:00.213)       0:03:04.951 *****
2025-10-08 12:18:14.134414 | controller | changed: [instance]
2025-10-08 12:18:14.153989 | controller |
2025-10-08 12:18:14.154033 | controller | TASK [dnsmasq : Stop service] **************************************************
2025-10-08 12:18:14.154041 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.756)       0:03:05.708 *****
2025-10-08 12:18:14.154052 | controller | skipping: [instance]
2025-10-08 12:18:14.154070 | controller |
2025-10-08 12:18:14.154078 | controller | TASK [dnsmasq : Remove unit file] **********************************************
2025-10-08 12:18:14.154165 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.019)       0:03:05.728 *****
2025-10-08 12:18:14.174996 | controller | skipping: [instance]
2025-10-08 12:18:14.175060 | controller |
2025-10-08 12:18:14.175072 | controller | TASK [dnsmasq : Remove main configuration files] *******************************
2025-10-08 12:18:14.175083 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.020)       0:03:05.749 *****
2025-10-08 12:18:14.203946 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.conf)
2025-10-08 12:18:14.204026 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.d)
2025-10-08 12:18:14.204040 | controller | skipping: [instance]
2025-10-08 12:18:14.204301 | controller |
2025-10-08 12:18:14.275164 | controller | TASK [Create dnsmasq networks] *************************************************
2025-10-08 12:18:14.275207 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.029)       0:03:05.778 *****
2025-10-08 12:18:14.275220 | controller |
2025-10-08 12:18:14.304445 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************
2025-10-08 12:18:14.304490 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.070)       0:03:05.849 *****
2025-10-08 12:18:14.304502 | controller | ok: [instance] => changed=false
2025-10-08 12:18:14.350912 | controller |   msg: All assertions passed
2025-10-08 12:18:14.350952 | controller |
2025-10-08 12:18:14.350983 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] *******************
2025-10-08 12:18:14.350991 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.029)       0:03:05.878 *****
2025-10-08 12:18:14.351003 | controller | ok: [instance] => changed=false
2025-10-08 12:18:14.351446 | controller |   msg: All assertions passed
2025-10-08 12:18:14.351462 | controller |
2025-10-08 12:18:14.827349 | controller | TASK [dnsmasq : Create network] ************************************************
2025-10-08 12:18:14.827382 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.046)       0:03:05.924 *****
2025-10-08 12:18:14.827394 | controller | changed: [instance]
2025-10-08 12:18:14.845571 | controller |
2025-10-08 12:18:14.845601 | controller | TASK [dnsmasq : Remove network] ************************************************
2025-10-08 12:18:14.845608 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.476)       0:03:06.401 *****
2025-10-08 12:18:14.845618 | controller | skipping: [instance]
2025-10-08 12:18:14.867653 | controller |
2025-10-08 12:18:14.867681 | controller | TASK [dnsmasq : Remove dhcp host files] ****************************************
2025-10-08 12:18:14.867689 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.018)       0:03:06.419 *****
2025-10-08 12:18:14.867700 | controller | skipping: [instance]
2025-10-08 12:18:15.184595 | controller |
2025-10-08 12:18:15.184627 | controller | TASK [libvirt_manager : Ensure network is in correct zone] *********************
2025-10-08 12:18:15.184635 | controller | Wednesday 08 October 2025  12:18:14 +0000 (0:00:00.022)       0:03:06.441 *****
2025-10-08 12:18:15.184653 | controller | changed: [instance] => (item=cifmw-public)
2025-10-08 12:18:15.214364 | controller |
2025-10-08 12:18:15.214398 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-10-08 12:18:15.214406 | controller | Wednesday 08 October 2025  12:18:15 +0000 (0:00:00.316)       0:03:06.758 *****
2025-10-08 12:18:15.214417 | 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-08 12:18:15.534475 | controller |
2025-10-08 12:18:15.534508 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-10-08 12:18:15.534516 | controller | Wednesday 08 October 2025  12:18:15 +0000 (0:00:00.029)       0:03:06.788 *****
2025-10-08 12:18:15.534526 | controller | ok: [instance]
2025-10-08 12:18:15.568908 | controller |
2025-10-08 12:18:15.568944 | controller | TASK [libvirt_manager : Set network_bridge_info fact with network and address] ***
2025-10-08 12:18:15.568952 | controller | Wednesday 08 October 2025  12:18:15 +0000 (0:00:00.320)       0:03:07.108 *****
2025-10-08 12:18:15.568976 | controller | ok: [instance]
2025-10-08 12:18:15.569143 | controller |
2025-10-08 12:18:15.569165 | controller | TASK [libvirt_manager : Output _network_data] **********************************
2025-10-08 12:18:15.931477 | controller | Wednesday 08 October 2025  12:18:15 +0000 (0:00:00.034)       0:03:07.143 *****
2025-10-08 12:18:15.931515 | controller | changed: [instance]
2025-10-08 12:18:16.288778 | controller |
2025-10-08 12:18:16.288831 | controller | TASK [libvirt_manager : Output pub_net] ****************************************
2025-10-08 12:18:16.288843 | controller | Wednesday 08 October 2025  12:18:15 +0000 (0:00:00.362)       0:03:07.505 *****
2025-10-08 12:18:16.288854 | controller | changed: [instance]
2025-10-08 12:18:16.637185 | controller |
2025-10-08 12:18:16.637218 | controller | TASK [libvirt_manager : Output _cifmw_libvirt_manager_layout] ******************
2025-10-08 12:18:16.637226 | controller | Wednesday 08 October 2025  12:18:16 +0000 (0:00:00.357)       0:03:07.862 *****
2025-10-08 12:18:16.637236 | controller | changed: [instance]
2025-10-08 12:18:16.735268 | controller |
2025-10-08 12:18:16.735301 | controller | TASK [libvirt_manager : Expose patch for networking_mapper] ********************
2025-10-08 12:18:16.735309 | controller | Wednesday 08 October 2025  12:18:16 +0000 (0:00:00.348)       0:03:08.211 *****
2025-10-08 12:18:16.735319 | controller | ok: [instance]
2025-10-08 12:18:17.097403 | controller |
2025-10-08 12:18:17.097436 | controller | TASK [libvirt_manager : Save networking_mapper patch] **************************
2025-10-08 12:18:17.097444 | controller | Wednesday 08 October 2025  12:18:16 +0000 (0:00:00.098)       0:03:08.309 *****
2025-10-08 12:18:17.097454 | controller | changed: [instance]
2025-10-08 12:18:17.122508 | controller |
2025-10-08 12:18:17.122541 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-10-08 12:18:17.122549 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.362)       0:03:08.671 *****
2025-10-08 12:18:17.122559 | controller | skipping: [instance]
2025-10-08 12:18:17.147461 | controller |
2025-10-08 12:18:17.147494 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-10-08 12:18:17.147503 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.025)       0:03:08.696 *****
2025-10-08 12:18:17.147513 | controller | skipping: [instance]
2025-10-08 12:18:17.173042 | controller |
2025-10-08 12:18:17.173077 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-10-08 12:18:17.173086 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.024)       0:03:08.721 *****
2025-10-08 12:18:17.173096 | controller | skipping: [instance]
2025-10-08 12:18:17.199629 | controller |
2025-10-08 12:18:17.199668 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-10-08 12:18:17.199676 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.025)       0:03:08.747 *****
2025-10-08 12:18:17.199686 | controller | skipping: [instance]
2025-10-08 12:18:17.219471 | controller |
2025-10-08 12:18:17.219505 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-10-08 12:18:17.219513 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.026)       0:03:08.773 *****
2025-10-08 12:18:17.219524 | controller | ok: [instance]
2025-10-08 12:18:17.301788 | controller |
2025-10-08 12:18:17.301844 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-10-08 12:18:17.301853 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.019)       0:03:08.793 *****
2025-10-08 12:18:17.301867 | 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, 'tools': {'multus': {'ranges': [{'start': 30, 'end': 39}]}, 'netconfig': {'ranges': [{'start': '192.168.122.40', 'end': '192.168.122.49'}]}, 'metallb': {'ranges': [{'start': '192.168.122.80', 'end': '192.168.122.90'}]}}}, 'internalapi': {'network': '172.17.0.0/24', 'gateway': '172.17.0.1', 'vlan': 20, 'mtu': 1496, 'tools': {'metallb': {'ranges': [{'start': '172.17.0.90', 'end': '172.17.0.100'}]}, 'netconfig': {'ranges': [{'start': '172.17.0.40', 'end': '172.17.0.49'}]}, 'multus': {'ranges': [{'start': 50, 'end': 59}]}}}, 'storage': {'network': '172.18.0.0/24', 'vlan': 21, 'mtu': 1496, 'tools': {'netconfig': {'ranges': [{'start': '172.18.0.40', 'end': '172.18.0.49'}]}}}, 'tenant': {'network': '172.19.0.0/24', 'gateway-v4': '172.19.0.1', 'search-domain': 'tenant.example.local', 'dns-v4': ['8.8.8.8', '172.19.0.1'], 'tools': {'netconfig': {'ranges': [{'start': '172.19.0.40', 'end': '172.19.0.49'}]}}, 'vlan': 22, 'mtu': 1496}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}, 'internalapi': {}, 'tenant': {}, 'storage': {}}}, 'sl-computes': {'network-template': {'range': {'start': 16, 'length': 2}}, 'networks': {'ctlplane': {}, 'internalapi': {}, 'tenant': {}, 'storage': {}}}, 'baremetals': {'networks': {'ctlplane': {'range': '192.168.122.20-192.168.122.24'}, 'internalapi': {'range': '20-24'}, 'tenant': {'range': {'start': 20, 'length': 5}}, 'storage': {'range': {'start': 20, 'length': 5}}}}}})
2025-10-08 12:18:17.319693 | controller | ok: [instance] => (item={'networks': {'public': {'network-v4': '192.168.110.0/24'}}, 'group-templates': {'computes': {'networks': {'public': None}}}})
2025-10-08 12:18:17.319726 | controller |
2025-10-08 12:18:17.319736 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-10-08 12:18:17.319743 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.081)       0:03:08.875 *****
2025-10-08 12:18:17.319755 | controller | skipping: [instance]
2025-10-08 12:18:17.532789 | controller |
2025-10-08 12:18:17.532840 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-10-08 12:18:17.532849 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.018)       0:03:08.893 *****
2025-10-08 12:18:17.532860 | controller | ok: [instance]
2025-10-08 12:18:17.958137 | controller |
2025-10-08 12:18:17.958167 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-10-08 12:18:17.958176 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.213)       0:03:09.106 *****
2025-10-08 12:18:17.958186 | controller | changed: [instance]
2025-10-08 12:18:18.008447 | controller |
2025-10-08 12:18:18.008475 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-10-08 12:18:18.008483 | controller | Wednesday 08 October 2025  12:18:17 +0000 (0:00:00.425)       0:03:09.532 *****
2025-10-08 12:18:18.008493 | controller | ok: [instance]
2025-10-08 12:18:18.034473 | controller |
2025-10-08 12:18:18.034503 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-10-08 12:18:18.034510 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.050)       0:03:09.582 *****
2025-10-08 12:18:18.034526 | controller | ok: [instance]
2025-10-08 12:18:18.450356 | controller |
2025-10-08 12:18:18.450388 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-10-08 12:18:18.450396 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.026)       0:03:09.608 *****
2025-10-08 12:18:18.450407 | controller | changed: [instance]
2025-10-08 12:18:18.473906 | controller |
2025-10-08 12:18:18.473944 | controller | TASK [libvirt_manager : Be sure to save current state of networking_mapper environment] ***
2025-10-08 12:18:18.473971 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.415)       0:03:10.024 *****
2025-10-08 12:18:18.473985 | controller | ok: [instance]
2025-10-08 12:18:18.474015 | controller |
2025-10-08 12:18:18.474025 | controller | TASK [libvirt_manager : Unset patch] *******************************************
2025-10-08 12:18:18.474161 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.023)       0:03:10.048 *****
2025-10-08 12:18:18.491898 | controller | ok: [instance]
2025-10-08 12:18:18.492054 | controller |
2025-10-08 12:18:18.492090 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_entries fact] ****************
2025-10-08 12:18:18.492103 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.017)       0:03:10.066 *****
2025-10-08 12:18:18.510884 | controller | ok: [instance]
2025-10-08 12:18:18.564058 | controller |
2025-10-08 12:18:18.564104 | controller | TASK [libvirt_manager : Reserve IPs on networks] *******************************
2025-10-08 12:18:18.564114 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.018)       0:03:10.085 *****
2025-10-08 12:18:18.564128 | 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-08 12:18:18.564170 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=internalapi)
2025-10-08 12:18:18.564179 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=storage)
2025-10-08 12:18:18.564186 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=tenant)
2025-10-08 12:18:18.564195 | 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-08 12:18:18.564464 | controller |
2025-10-08 12:18:18.617902 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-08 12:18:18.617938 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.053)       0:03:10.138 *****
2025-10-08 12:18:18.617952 | controller | skipping: [instance] => (item=compute-0 - ctlplane)
2025-10-08 12:18:18.617996 | controller | skipping: [instance]
2025-10-08 12:18:18.618004 | controller |
2025-10-08 12:18:18.618014 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-08 12:18:18.618125 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.053)       0:03:10.192 *****
2025-10-08 12:18:18.673890 | controller | skipping: [instance] => (item=compute-0 - internalapi)
2025-10-08 12:18:18.673932 | controller | skipping: [instance]
2025-10-08 12:18:18.673942 | controller |
2025-10-08 12:18:18.674177 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-08 12:18:18.780032 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.056)       0:03:10.248 *****
2025-10-08 12:18:18.780081 | controller | skipping: [instance] => (item=compute-0 - storage)
2025-10-08 12:18:18.780101 | controller | skipping: [instance]
2025-10-08 12:18:18.780108 | controller |
2025-10-08 12:18:18.780115 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-08 12:18:18.780180 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.105)       0:03:10.354 *****
2025-10-08 12:18:18.834902 | controller | skipping: [instance] => (item=compute-0 - tenant)
2025-10-08 12:18:18.834943 | controller | skipping: [instance]
2025-10-08 12:18:18.834953 | controller |
2025-10-08 12:18:18.835131 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-08 12:18:18.910498 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.055)       0:03:10.409 *****
2025-10-08 12:18:18.910532 | controller | ok: [instance] => (item=compute-0 - public)
2025-10-08 12:18:18.986306 | controller |
2025-10-08 12:18:18.986339 | controller | TASK [Inject DHCP entries for net {{ net_name }}] ******************************
2025-10-08 12:18:18.986346 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.075)       0:03:10.484 *****
2025-10-08 12:18:18.986358 | controller |
2025-10-08 12:18:19.025746 | controller | TASK [dnsmasq : Ensure we have the right data and type] ************************
2025-10-08 12:18:19.025782 | controller | Wednesday 08 October 2025  12:18:18 +0000 (0:00:00.075)       0:03:10.560 *****
2025-10-08 12:18:19.025794 | controller | ok: [instance]
2025-10-08 12:18:19.071427 | controller |
2025-10-08 12:18:19.071459 | controller | TASK [dnsmasq : Assert we have needed host data] *******************************
2025-10-08 12:18:19.071467 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.039)       0:03:10.599 *****
2025-10-08 12:18:19.071478 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:27:91:10', 'ips': ['192.168.110.10', '']})
2025-10-08 12:18:19.115951 | controller |
2025-10-08 12:18:19.116002 | controller | TASK [dnsmasq : Ensure networks exists] ****************************************
2025-10-08 12:18:19.116010 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.045)       0:03:10.645 *****
2025-10-08 12:18:19.116023 | 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-08 12:18:19.300835 | controller |
2025-10-08 12:18:19.300869 | controller | TASK [dnsmasq : Check network file status] *************************************
2025-10-08 12:18:19.300877 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.044)       0:03:10.690 *****
2025-10-08 12:18:19.300888 | controller | ok: [instance]
2025-10-08 12:18:19.323922 | controller |
2025-10-08 12:18:19.323969 | controller | TASK [dnsmasq : Assert network exists] *****************************************
2025-10-08 12:18:19.323985 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.184)       0:03:10.874 *****
2025-10-08 12:18:19.323997 | controller | ok: [instance]
2025-10-08 12:18:19.324049 | controller |
2025-10-08 12:18:19.324077 | controller | TASK [dnsmasq : Initialize empty dhcp_host_entries] ****************************
2025-10-08 12:18:19.324090 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.023)       0:03:10.898 *****
2025-10-08 12:18:19.343039 | controller | ok: [instance]
2025-10-08 12:18:19.423879 | controller |
2025-10-08 12:18:19.423911 | controller | TASK [dnsmasq : Compute entry] *************************************************
2025-10-08 12:18:19.423919 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.019)       0:03:10.917 *****
2025-10-08 12:18:19.423934 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:27:91:10', 'ips': ['192.168.110.10', '']})
2025-10-08 12:18:19.424007 | controller |
2025-10-08 12:18:19.424016 | controller | TASK [dnsmasq : Create add/remove sets] ****************************************
2025-10-08 12:18:19.424024 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.080)       0:03:10.998 *****
2025-10-08 12:18:19.460607 | controller | ok: [instance]
2025-10-08 12:18:19.833581 | controller |
2025-10-08 12:18:19.833613 | controller | TASK [dnsmasq : Add DHCP entries] **********************************************
2025-10-08 12:18:19.833622 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.036)       0:03:11.034 *****
2025-10-08 12:18:19.833633 | controller | changed: [instance] => (item={'file': 'public_compute-0_52:54:00:27:91:10', 'entry': '52:54:00:27:91:10,192.168.110.10,compute-0', 'state': 'present'})
2025-10-08 12:18:19.855905 | controller |
2025-10-08 12:18:19.855943 | controller | TASK [dnsmasq : Remove DHCP entries] *******************************************
2025-10-08 12:18:19.855974 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.372)       0:03:11.407 *****
2025-10-08 12:18:19.855988 | controller | skipping: [instance]
2025-10-08 12:18:19.958922 | controller |
2025-10-08 12:18:19.958967 | controller | TASK [libvirt_manager : Create per-network and .utility DNS entries] ***********
2025-10-08 12:18:19.958977 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.022)       0:03:11.429 *****
2025-10-08 12:18:19.958988 | controller | ok: [instance] => (item=compute-0)
2025-10-08 12:18:19.959005 | controller |
2025-10-08 12:18:19.959013 | controller | TASK [Inject VMs in the .utility zone] *****************************************
2025-10-08 12:18:19.959125 | controller | Wednesday 08 October 2025  12:18:19 +0000 (0:00:00.103)       0:03:11.533 *****
2025-10-08 12:18:20.042852 | controller |
2025-10-08 12:18:20.084946 | controller | TASK [dnsmasq : Assert we have needed host record data] ************************
2025-10-08 12:18:20.084999 | controller | Wednesday 08 October 2025  12:18:20 +0000 (0:00:00.083)       0:03:11.616 *****
2025-10-08 12:18:20.085020 | controller | ok: [instance]
2025-10-08 12:18:20.085053 | controller |
2025-10-08 12:18:20.085064 | controller | TASK [dnsmasq : Assert each address element have needed data] ******************
2025-10-08 12:18:20.085153 | controller | Wednesday 08 October 2025  12:18:20 +0000 (0:00:00.042)       0:03:11.659 *****
2025-10-08 12:18:20.193453 | 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-08 12:18:20.193941 | controller | ok: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-08 12:18:20.193969 | controller | ok: [instance] => (item={'names': ['compute-0.internalapi.local', 'compute-0.internalapi.local'], 'ips': ['172.17.0.10', ''], 'state': 'present'})
2025-10-08 12:18:20.193978 | controller | ok: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.110.10', ''], 'state': 'present'})
2025-10-08 12:18:20.193984 | controller | ok: [instance] => (item={'names': ['compute-0.storage.local', 'compute-0.storage.local'], 'ips': ['172.18.0.10', ''], 'state': 'present'})
2025-10-08 12:18:20.193992 | controller | ok: [instance] => (item={'names': ['compute-0.tenant.local', 'compute-0.tenant.local'], 'ips': ['172.19.0.10', ''], 'state': 'present'})
2025-10-08 12:18:21.585499 | controller |
2025-10-08 12:18:21.585532 | controller | TASK [dnsmasq : Add/Remove address] ********************************************
2025-10-08 12:18:21.585540 | controller | Wednesday 08 October 2025  12:18:20 +0000 (0:00:00.107)       0:03:11.767 *****
2025-10-08 12:18:21.585551 | 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-08 12:18:21.979175 | controller | changed: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-08 12:18:21.979208 | controller | changed: [instance] => (item={'names': ['compute-0.internalapi.local', 'compute-0.internalapi.local'], 'ips': ['172.17.0.10', ''], 'state': 'present'})
2025-10-08 12:18:21.979216 | controller | changed: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.110.10', ''], 'state': 'present'})
2025-10-08 12:18:21.979222 | controller | changed: [instance] => (item={'names': ['compute-0.storage.local', 'compute-0.storage.local'], 'ips': ['172.18.0.10', ''], 'state': 'present'})
2025-10-08 12:18:21.979228 | controller | changed: [instance] => (item={'names': ['compute-0.tenant.local', 'compute-0.tenant.local'], 'ips': ['172.19.0.10', ''], 'state': 'present'})
2025-10-08 12:18:21.979234 | controller |
2025-10-08 12:18:21.979240 | controller | TASK [libvirt_manager : Ensure some domains are local] *************************
2025-10-08 12:18:21.979246 | controller | Wednesday 08 October 2025  12:18:21 +0000 (0:00:01.391)       0:03:13.159 *****
2025-10-08 12:18:21.979255 | controller | changed: [instance]
2025-10-08 12:18:22.834259 | controller |
2025-10-08 12:18:22.834293 | controller | TASK [libvirt_manager : Ensure dnsmasq is reloaded now] ************************
2025-10-08 12:18:22.834301 | controller | Wednesday 08 October 2025  12:18:21 +0000 (0:00:00.383)       0:03:13.543 *****
2025-10-08 12:18:22.834307 | controller |
2025-10-08 12:18:22.834313 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-10-08 12:18:22.834319 | controller | Wednesday 08 October 2025  12:18:21 +0000 (0:00:00.009)       0:03:13.552 *****
2025-10-08 12:18:22.834329 | controller | changed: [instance]
2025-10-08 12:18:23.205911 | controller |
2025-10-08 12:18:23.205944 | controller | RUNNING HANDLER [dnsmasq : Restart dnsmasq] ************************************
2025-10-08 12:18:23.205966 | controller | Wednesday 08 October 2025  12:18:22 +0000 (0:00:00.855)       0:03:14.408 *****
2025-10-08 12:18:23.205977 | controller | changed: [instance]
2025-10-08 12:18:23.589312 | controller |
2025-10-08 12:18:23.589348 | controller | RUNNING HANDLER [dnsmasq : Reload dnsmasq] *************************************
2025-10-08 12:18:23.589357 | controller | Wednesday 08 October 2025  12:18:23 +0000 (0:00:00.371)       0:03:14.779 *****
2025-10-08 12:18:23.589380 | controller | changed: [instance]
2025-10-08 12:18:24.005637 | controller |
2025-10-08 12:18:24.005669 | controller | TASK [libvirt_manager : Create group inventories] ******************************
2025-10-08 12:18:24.005677 | controller | Wednesday 08 October 2025  12:18:23 +0000 (0:00:00.383)       0:03:15.163 *****
2025-10-08 12:18:24.005688 | controller | changed: [instance] => (item=compute)
2025-10-08 12:18:24.404092 | controller |
2025-10-08 12:18:24.404130 | controller | TASK [libvirt_manager : Create "all" group inventory file] *********************
2025-10-08 12:18:24.404138 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.416)       0:03:15.579 *****
2025-10-08 12:18:24.404149 | controller | changed: [instance]
2025-10-08 12:18:24.441040 | controller |
2025-10-08 12:18:24.441076 | controller | TASK [libvirt_manager : Ensure storage pool is present.] ***********************
2025-10-08 12:18:24.441084 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.398)       0:03:15.978 *****
2025-10-08 12:18:24.441095 | controller | skipping: [instance]
2025-10-08 12:18:24.514979 | controller |
2025-10-08 12:18:24.515012 | controller | TASK [libvirt_manager : Ensure images are present] *****************************
2025-10-08 12:18:24.515020 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.036)       0:03:16.015 *****
2025-10-08 12:18:24.515031 | 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-08 12:18:24.515059 | controller |
2025-10-08 12:18:24.515067 | controller | TASK [libvirt_manager : Ensure directory exists] *******************************
2025-10-08 12:18:24.515180 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.074)       0:03:16.089 *****
2025-10-08 12:18:24.533897 | controller | skipping: [instance]
2025-10-08 12:18:24.553605 | controller |
2025-10-08 12:18:24.553638 | controller | TASK [libvirt_manager : Check if base image exists] ****************************
2025-10-08 12:18:24.553647 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.019)       0:03:16.108 *****
2025-10-08 12:18:24.553657 | controller | skipping: [instance]
2025-10-08 12:18:24.573591 | controller |
2025-10-08 12:18:24.573635 | controller | TASK [libvirt_manager : Download base image] ***********************************
2025-10-08 12:18:24.573646 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.019)       0:03:16.127 *****
2025-10-08 12:18:24.573658 | controller | skipping: [instance]
2025-10-08 12:18:24.594545 | controller |
2025-10-08 12:18:24.594581 | controller | TASK [libvirt_manager : Check image] *******************************************
2025-10-08 12:18:24.594590 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.019)       0:03:16.147 *****
2025-10-08 12:18:24.594600 | controller | skipping: [instance]
2025-10-08 12:18:24.614461 | controller |
2025-10-08 12:18:24.614507 | controller | TASK [libvirt_manager : Assert image status] ***********************************
2025-10-08 12:18:24.614515 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.020)       0:03:16.168 *****
2025-10-08 12:18:24.614526 | controller | skipping: [instance]
2025-10-08 12:18:24.634716 | controller |
2025-10-08 12:18:24.634753 | controller | TASK [libvirt_manager : Ensure image access rights] ****************************
2025-10-08 12:18:24.634762 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.019)       0:03:16.188 *****
2025-10-08 12:18:24.634772 | controller | skipping: [instance]
2025-10-08 12:18:24.829196 | controller |
2025-10-08 12:18:24.829231 | controller | TASK [libvirt_manager : Get ssh key state] *************************************
2025-10-08 12:18:24.829240 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.020)       0:03:16.208 *****
2025-10-08 12:18:24.829250 | controller | ok: [instance]
2025-10-08 12:18:25.223462 | controller |
2025-10-08 12:18:25.223493 | controller | TASK [libvirt_manager : Create temporary ssh keypair] **************************
2025-10-08 12:18:25.223502 | controller | Wednesday 08 October 2025  12:18:24 +0000 (0:00:00.194)       0:03:16.403 *****
2025-10-08 12:18:25.223513 | controller | changed: [instance]
2025-10-08 12:18:25.526925 | controller |
2025-10-08 12:18:25.526970 | controller | TASK [libvirt_manager : Slurp public key for later use] ************************
2025-10-08 12:18:25.526980 | controller | Wednesday 08 October 2025  12:18:25 +0000 (0:00:00.394)       0:03:16.797 *****
2025-10-08 12:18:25.526991 | controller | ok: [instance]
2025-10-08 12:18:25.527307 | controller |
2025-10-08 12:18:25.707639 | controller | TASK [libvirt_manager : Slurp private key for later use] ***********************
2025-10-08 12:18:25.707673 | controller | Wednesday 08 October 2025  12:18:25 +0000 (0:00:00.303)       0:03:17.101 *****
2025-10-08 12:18:25.707685 | controller | ok: [instance]
2025-10-08 12:18:26.088778 | controller |
2025-10-08 12:18:26.088833 | controller | TASK [libvirt_manager : Inject cifmw_reproducer_key.pub in hypervisor authorized_keys] ***
2025-10-08 12:18:26.088844 | controller | Wednesday 08 October 2025  12:18:25 +0000 (0:00:00.180)       0:03:17.281 *****
2025-10-08 12:18:26.088856 | controller | changed: [instance]
2025-10-08 12:18:26.107902 | controller |
2025-10-08 12:18:26.107938 | controller | TASK [libvirt_manager : Create fact holding network data for VMs] **************
2025-10-08 12:18:26.107967 | controller | Wednesday 08 October 2025  12:18:26 +0000 (0:00:00.381)       0:03:17.662 *****
2025-10-08 12:18:26.107980 | controller | ok: [instance]
2025-10-08 12:18:26.349429 | controller |
2025-10-08 12:18:26.349462 | controller | TASK [libvirt_manager : List existing networks] ********************************
2025-10-08 12:18:26.349471 | controller | Wednesday 08 October 2025  12:18:26 +0000 (0:00:00.019)       0:03:17.682 *****
2025-10-08 12:18:26.349481 | controller | ok: [instance]
2025-10-08 12:18:26.740714 | controller |
2025-10-08 12:18:26.740750 | controller | TASK [libvirt_manager : Gather pool fact] **************************************
2025-10-08 12:18:26.740758 | controller | Wednesday 08 October 2025  12:18:26 +0000 (0:00:00.241)       0:03:17.923 *****
2025-10-08 12:18:26.740769 | controller | ok: [instance]
2025-10-08 12:18:26.805454 | controller |
2025-10-08 12:18:26.805492 | controller | TASK [libvirt_manager : Create and run VMs] ************************************
2025-10-08 12:18:26.805500 | controller | Wednesday 08 October 2025  12:18:26 +0000 (0:00:00.391)       0:03:18.314 *****
2025-10-08 12:18:26.805511 | 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-08 12:18:27.075893 | controller |
2025-10-08 12:18:27.075924 | controller | TASK [libvirt_manager : Create VM image for compute-0] *************************
2025-10-08 12:18:27.075933 | controller | Wednesday 08 October 2025  12:18:26 +0000 (0:00:00.064)       0:03:18.379 *****
2025-10-08 12:18:27.075943 | controller | changed: [instance]
2025-10-08 12:18:27.310704 | controller |
2025-10-08 12:18:27.310738 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-0] ********
2025-10-08 12:18:27.310747 | controller | Wednesday 08 October 2025  12:18:27 +0000 (0:00:00.270)       0:03:18.649 *****
2025-10-08 12:18:27.310757 | controller | changed: [instance]
2025-10-08 12:18:28.392386 | controller |
2025-10-08 12:18:28.392418 | controller | TASK [libvirt_manager : Define VMs for type compute-0] *************************
2025-10-08 12:18:28.392426 | controller | Wednesday 08 October 2025  12:18:27 +0000 (0:00:00.234)       0:03:18.884 *****
2025-10-08 12:18:28.392436 | controller | changed: [instance]
2025-10-08 12:18:28.418464 | controller |
2025-10-08 12:18:28.418497 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-0] ***********
2025-10-08 12:18:28.418506 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:01.081)       0:03:19.966 *****
2025-10-08 12:18:28.418516 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2025-10-08 12:18:28.451978 | controller |
2025-10-08 12:18:28.452020 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2025-10-08 12:18:28.452031 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:00.026)       0:03:19.992 *****
2025-10-08 12:18:28.452043 | 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-08 12:18:28.684515 | controller |
2025-10-08 12:18:28.684558 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2025-10-08 12:18:28.684567 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:00.033)       0:03:20.025 *****
2025-10-08 12:18:28.684577 | controller | ok: [instance]
2025-10-08 12:18:28.684596 | controller |
2025-10-08 12:18:28.684832 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2025-10-08 12:18:28.728591 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:00.232)       0:03:20.258 *****
2025-10-08 12:18:28.728629 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:18:28.966431 | controller | ok: [instance] => (item=default)
2025-10-08 12:18:28.966464 | controller |
2025-10-08 12:18:28.966472 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2025-10-08 12:18:28.966478 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:00.043)       0:03:20.302 *****
2025-10-08 12:18:28.966488 | controller | ok: [instance]
2025-10-08 12:18:29.175182 | controller |
2025-10-08 12:18:29.175212 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2025-10-08 12:18:29.175220 | controller | Wednesday 08 October 2025  12:18:28 +0000 (0:00:00.237)       0:03:20.540 *****
2025-10-08 12:18:29.175231 | controller | ok: [instance]
2025-10-08 12:18:29.470901 | controller |
2025-10-08 12:18:29.470938 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-0] ************
2025-10-08 12:18:29.470946 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.208)       0:03:20.749 *****
2025-10-08 12:18:29.470972 | controller | changed: [instance]
2025-10-08 12:18:29.471000 | controller |
2025-10-08 12:18:29.471301 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-0] *****
2025-10-08 12:18:29.491662 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.295)       0:03:21.045 *****
2025-10-08 12:18:29.491702 | controller | skipping: [instance]
2025-10-08 12:18:29.518419 | controller |
2025-10-08 12:18:29.518451 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-0] ********
2025-10-08 12:18:29.518459 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.020)       0:03:21.065 *****
2025-10-08 12:18:29.518476 | controller | skipping: [instance]
2025-10-08 12:18:29.545126 | controller |
2025-10-08 12:18:29.545169 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-0] **************
2025-10-08 12:18:29.545178 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.026)       0:03:21.092 *****
2025-10-08 12:18:29.545189 | controller | skipping: [instance]
2025-10-08 12:18:29.569776 | controller |
2025-10-08 12:18:29.569838 | controller | TASK [libvirt_manager : Attach volumes for VM compute-0] ***********************
2025-10-08 12:18:29.569851 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.026)       0:03:21.119 *****
2025-10-08 12:18:29.569865 | controller | skipping: [instance]
2025-10-08 12:18:29.569941 | controller |
2025-10-08 12:18:29.570098 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2025-10-08 12:18:29.570218 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.025)       0:03:21.144 *****
2025-10-08 12:18:29.803388 | controller | changed: [instance]
2025-10-08 12:18:29.839319 | controller |
2025-10-08 12:18:29.839357 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2025-10-08 12:18:29.839367 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.233)       0:03:21.377 *****
2025-10-08 12:18:29.839379 | controller | ok: [instance]
2025-10-08 12:18:29.860286 | controller |
2025-10-08 12:18:29.860318 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2025-10-08 12:18:29.860326 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.036)       0:03:21.413 *****
2025-10-08 12:18:29.860337 | controller | skipping: [instance]
2025-10-08 12:18:29.880729 | controller |
2025-10-08 12:18:29.880757 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2025-10-08 12:18:29.880764 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.021)       0:03:21.434 *****
2025-10-08 12:18:29.880774 | controller | skipping: [instance]
2025-10-08 12:18:29.927354 | controller |
2025-10-08 12:18:29.927388 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2025-10-08 12:18:29.927396 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.020)       0:03:21.454 *****
2025-10-08 12:18:29.927407 | controller | skipping: [instance]
2025-10-08 12:18:29.963644 | controller |
2025-10-08 12:18:29.963681 | controller | TASK [libvirt_manager : Start (power-on) VMs] **********************************
2025-10-08 12:18:29.963690 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.046)       0:03:21.501 *****
2025-10-08 12:18:29.963709 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/start_vms.yml for instance
2025-10-08 12:18:29.994169 | controller |
2025-10-08 12:18:29.994201 | controller | TASK [libvirt_manager : Refresh oooq_pool before starting VMs] *****************
2025-10-08 12:18:29.994209 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.036)       0:03:21.537 *****
2025-10-08 12:18:29.994219 | controller | skipping: [instance]
2025-10-08 12:18:29.994363 | controller |
2025-10-08 12:18:29.994512 | controller | TASK [libvirt_manager : Start VMs for type {{ vm_type }}] **********************
2025-10-08 12:18:29.994670 | controller | Wednesday 08 October 2025  12:18:29 +0000 (0:00:00.031)       0:03:21.568 *****
2025-10-08 12:18:30.032555 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-08 12:18:30.032760 | controller | skipping: [instance]
2025-10-08 12:18:30.032990 | controller |
2025-10-08 12:18:30.033174 | controller | TASK [libvirt_manager : Wait for SSH on started VMs] ***************************
2025-10-08 12:18:30.033317 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.038)       0:03:21.606 *****
2025-10-08 12:18:30.077239 | controller | skipping: [instance] => (item=compute-0.utility)
2025-10-08 12:18:30.077419 | controller | skipping: [instance]
2025-10-08 12:18:30.077560 | controller |
2025-10-08 12:18:30.077703 | controller | TASK [libvirt_manager : Ensure we get SSH on nodes] ****************************
2025-10-08 12:18:30.077869 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.044)       0:03:21.651 *****
2025-10-08 12:18:30.104339 | 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-08 12:18:30.104513 | controller | skipping: [instance]
2025-10-08 12:18:30.104651 | controller |
2025-10-08 12:18:30.104820 | controller | TASK [libvirt_manager : Configure managed VMs] *********************************
2025-10-08 12:18:30.105009 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.027)       0:03:21.678 *****
2025-10-08 12:18:30.141324 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-08 12:18:30.141517 | controller | skipping: [instance]
2025-10-08 12:18:30.141651 | controller |
2025-10-08 12:18:30.141790 | controller | TASK [Create VBMC entity] ******************************************************
2025-10-08 12:18:30.141991 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.036)       0:03:21.715 *****
2025-10-08 12:18:30.179831 | controller | skipping: [instance] => (item=compute-0)
2025-10-08 12:18:30.416365 | controller | skipping: [instance]
2025-10-08 12:18:30.416397 | controller |
2025-10-08 12:18:30.416405 | controller | TASK [libvirt_manager : List running virtual machines.] ************************
2025-10-08 12:18:30.416412 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.038)       0:03:21.753 *****
2025-10-08 12:18:30.416422 | controller | ok: [instance]
2025-10-08 12:18:30.785713 | controller |
2025-10-08 12:18:30.785746 | controller | TASK [libvirt_manager : Dump UUIDs] ********************************************
2025-10-08 12:18:30.785760 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.236)       0:03:21.990 *****
2025-10-08 12:18:30.785771 | controller | changed: [instance]
2025-10-08 12:18:30.817461 | controller |
2025-10-08 12:18:30.817496 | controller | TASK [Ensure fresh vbmc listing] ***********************************************
2025-10-08 12:18:30.817504 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.369)       0:03:22.359 *****
2025-10-08 12:18:30.817514 | controller | skipping: [instance]
2025-10-08 12:18:30.848845 | controller |
2025-10-08 12:18:30.848879 | controller | TASK [libvirt_manager : Update vbmc related fact] ******************************
2025-10-08 12:18:30.848887 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.031)       0:03:22.391 *****
2025-10-08 12:18:30.848897 | controller | skipping: [instance]
2025-10-08 12:18:30.881519 | controller |
2025-10-08 12:18:30.881553 | controller | TASK [libvirt_manager : Dump vbmc known hosts] *********************************
2025-10-08 12:18:30.881562 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.031)       0:03:22.422 *****
2025-10-08 12:18:30.881574 | controller | skipping: [instance]
2025-10-08 12:18:30.905311 | controller |
2025-10-08 12:18:30.905349 | controller | TASK [libvirt_manager : Copy authorized_keys] **********************************
2025-10-08 12:18:30.905358 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.032)       0:03:22.455 *****
2025-10-08 12:18:30.905368 | controller | skipping: [instance]
2025-10-08 12:18:30.905560 | controller |
2025-10-08 12:18:30.905723 | controller | TASK [libvirt_manager : Enable root access on CRC] *****************************
2025-10-08 12:18:30.905894 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.024)       0:03:22.479 *****
2025-10-08 12:18:30.949023 | controller | skipping: [instance]
2025-10-08 12:18:30.949144 | controller |
2025-10-08 12:18:30.949303 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:18:30.949468 | controller | instance                   : ok=190  changed=92   unreachable=0    failed=0    skipped=89   rescued=0    ignored=0
2025-10-08 12:18:30.949604 | controller |
2025-10-08 12:18:30.949740 | controller | Wednesday 08 October 2025  12:18:30 +0000 (0:00:00.043)       0:03:22.523 *****
2025-10-08 12:18:30.949910 | controller | ===============================================================================
2025-10-08 12:18:30.950075 | controller | libvirt_manager : Install packages required for using KVM -------------- 75.28s
2025-10-08 12:18:30.950218 | controller | test_deps : Install selinux python libs -------------------------------- 43.69s
2025-10-08 12:18:30.950352 | controller | ci_nmstate : Install required packages on instance --------------------- 10.95s
2025-10-08 12:18:30.950483 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.08s
2025-10-08 12:18:30.950614 | controller | test_deps : Install extra packages -------------------------------------- 3.86s
2025-10-08 12:18:30.950745 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 3.59s
2025-10-08 12:18:30.950901 | controller | ci_nmstate : Apply the desidered state on instance ---------------------- 1.75s
2025-10-08 12:18:30.951061 | controller | discover_latest_image : Get latest image -------------------------------- 1.66s
2025-10-08 12:18:30.951192 | controller | libvirt_manager : Restart firewalld ------------------------------------- 1.60s
2025-10-08 12:18:30.951325 | controller | dnsmasq : Add/Remove address -------------------------------------------- 1.39s
2025-10-08 12:18:30.951459 | controller | test_deps : Install python yaml libs ------------------------------------ 1.28s
2025-10-08 12:18:30.951593 | controller | dnsmasq : Install needed packages --------------------------------------- 1.22s
2025-10-08 12:18:30.951727 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.19s
2025-10-08 12:18:30.951890 | controller | libvirt_manager : Define VMs for type compute-0 ------------------------- 1.08s
2025-10-08 12:18:30.952048 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.87s
2025-10-08 12:18:30.952185 | controller | Gathering Facts --------------------------------------------------------- 0.86s
2025-10-08 12:18:30.952318 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.85s
2025-10-08 12:18:30.952457 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.83s
2025-10-08 12:18:30.952588 | controller | libvirt_manager : Ensure networks are defined --------------------------- 0.77s
2025-10-08 12:18:30.952716 | controller | dnsmasq : Enable and start service -------------------------------------- 0.76s
2025-10-08 12:18:31.033064 | controller | INFO     Running default > converge
2025-10-08 12:18:31.519292 | controller |
2025-10-08 12:18:32.371843 | controller | PLAY [Converge] ****************************************************************
2025-10-08 12:18:32.371876 | controller |
2025-10-08 12:18:32.371885 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:18:32.371891 | controller | Wednesday 08 October 2025  12:18:31 +0000 (0:00:00.020)       0:00:00.020 *****
2025-10-08 12:18:32.371900 | controller | ok: [instance]
2025-10-08 12:18:32.683412 | controller |
2025-10-08 12:18:32.683446 | controller | TASK [virtualbmc : Ensure needed directories exist] ****************************
2025-10-08 12:18:32.683455 | controller | Wednesday 08 October 2025  12:18:32 +0000 (0:00:00.853)       0:00:00.873 *****
2025-10-08 12:18:32.683465 | controller | ok: [instance] => (item={'key': '/home/zuul/.ssh', 'mode': '0700'})
2025-10-08 12:18:34.067478 | controller |
2025-10-08 12:18:34.067511 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-10-08 12:18:34.067519 | controller | Wednesday 08 October 2025  12:18:32 +0000 (0:00:00.311)       0:00:01.185 *****
2025-10-08 12:18:34.067529 | controller | ok: [instance]
2025-10-08 12:18:34.389628 | controller |
2025-10-08 12:18:34.389661 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-10-08 12:18:34.389670 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:01.384)       0:00:02.569 *****
2025-10-08 12:18:34.389680 | controller | changed: [instance]
2025-10-08 12:18:34.414829 | controller |
2025-10-08 12:18:34.414866 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-10-08 12:18:34.414874 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:00.322)       0:00:02.891 *****
2025-10-08 12:18:34.414884 | controller | skipping: [instance]
2025-10-08 12:18:34.435979 | controller |
2025-10-08 12:18:34.436014 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-10-08 12:18:34.436022 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:00.025)       0:00:02.916 *****
2025-10-08 12:18:34.436032 | controller | skipping: [instance]
2025-10-08 12:18:34.436057 | controller |
2025-10-08 12:18:34.436065 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-10-08 12:18:34.436212 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:00.021)       0:00:02.937 *****
2025-10-08 12:18:34.462430 | controller | skipping: [instance]
2025-10-08 12:18:34.903666 | controller |
2025-10-08 12:18:34.903697 | controller | TASK [virtualbmc : Check if container already exists] **************************
2025-10-08 12:18:34.903706 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:00.026)       0:00:02.964 *****
2025-10-08 12:18:34.903715 | controller | ok: [instance]
2025-10-08 12:18:35.285328 | controller |
2025-10-08 12:18:35.285359 | controller | TASK [virtualbmc : Create ssh key for VBMC] ************************************
2025-10-08 12:18:35.285367 | controller | Wednesday 08 October 2025  12:18:34 +0000 (0:00:00.441)       0:00:03.405 *****
2025-10-08 12:18:35.285378 | controller | changed: [instance]
2025-10-08 12:18:41.526319 | controller |
2025-10-08 12:18:41.526352 | controller | TASK [virtualbmc : Pull vbmc container image] **********************************
2025-10-08 12:18:41.526361 | controller | Wednesday 08 October 2025  12:18:35 +0000 (0:00:00.381)       0:00:03.786 *****
2025-10-08 12:18:41.526371 | controller | changed: [instance]
2025-10-08 12:18:41.913124 | controller |
2025-10-08 12:18:41.913155 | controller | TASK [virtualbmc : Allow VBMC temporary key] ***********************************
2025-10-08 12:18:41.913163 | controller | Wednesday 08 October 2025  12:18:41 +0000 (0:00:06.241)       0:00:10.028 *****
2025-10-08 12:18:41.913173 | controller | changed: [instance]
2025-10-08 12:18:42.475200 | controller |
2025-10-08 12:18:42.475232 | controller | TASK [virtualbmc : Create ssh_config snippet for VBMC] *************************
2025-10-08 12:18:42.475240 | controller | Wednesday 08 October 2025  12:18:41 +0000 (0:00:00.386)       0:00:10.414 *****
2025-10-08 12:18:42.475250 | controller | changed: [instance]
2025-10-08 12:18:42.836918 | controller |
2025-10-08 12:18:42.836977 | controller | TASK [virtualbmc : Create vbmc server configuration file] **********************
2025-10-08 12:18:42.836988 | controller | Wednesday 08 October 2025  12:18:42 +0000 (0:00:00.562)       0:00:10.976 *****
2025-10-08 12:18:42.836999 | controller | changed: [instance]
2025-10-08 12:18:43.193901 | controller |
2025-10-08 12:18:43.193942 | controller | TASK [virtualbmc : Create undying vbmcd service script] ************************
2025-10-08 12:18:43.193985 | controller | Wednesday 08 October 2025  12:18:42 +0000 (0:00:00.361)       0:00:11.338 *****
2025-10-08 12:18:43.193997 | controller | changed: [instance]
2025-10-08 12:18:43.929511 | controller |
2025-10-08 12:18:43.929544 | controller | TASK [virtualbmc : Create and start vbmc container] ****************************
2025-10-08 12:18:43.929552 | controller | Wednesday 08 October 2025  12:18:43 +0000 (0:00:00.356)       0:00:11.695 *****
2025-10-08 12:18:43.929562 | controller | changed: [instance]
2025-10-08 12:18:43.956522 | controller |
2025-10-08 12:18:43.956553 | controller | TASK [virtualbmc : Assert we have required data] *******************************
2025-10-08 12:18:43.956561 | controller | Wednesday 08 October 2025  12:18:43 +0000 (0:00:00.735)       0:00:12.431 *****
2025-10-08 12:18:43.956576 | controller | ok: [instance] => changed=false
2025-10-08 12:18:44.443216 | controller |   msg: All assertions passed
2025-10-08 12:18:44.443247 | controller |
2025-10-08 12:18:44.443256 | controller | TASK [virtualbmc : Get existing known VBMC nodes] ******************************
2025-10-08 12:18:44.443263 | controller | Wednesday 08 October 2025  12:18:43 +0000 (0:00:00.027)       0:00:12.458 *****
2025-10-08 12:18:44.443273 | controller | changed: [instance]
2025-10-08 12:18:44.472466 | controller |
2025-10-08 12:18:44.472499 | controller | TASK [virtualbmc : Expose known hosts] *****************************************
2025-10-08 12:18:44.472507 | controller | Wednesday 08 October 2025  12:18:44 +0000 (0:00:00.486)       0:00:12.944 *****
2025-10-08 12:18:44.472518 | controller | ok: [instance]
2025-10-08 12:18:44.496384 | controller |
2025-10-08 12:18:44.496413 | controller | TASK [virtualbmc : Stop host in VBMC] ******************************************
2025-10-08 12:18:44.496421 | controller | Wednesday 08 October 2025  12:18:44 +0000 (0:00:00.029)       0:00:12.974 *****
2025-10-08 12:18:44.496431 | controller | skipping: [instance]
2025-10-08 12:18:45.191666 | controller |
2025-10-08 12:18:45.191702 | controller | TASK [virtualbmc : Add new host to VBMC] ***************************************
2025-10-08 12:18:45.191712 | controller | Wednesday 08 October 2025  12:18:44 +0000 (0:00:00.023)       0:00:12.998 *****
2025-10-08 12:18:45.191724 | controller | changed: [instance]
2025-10-08 12:18:45.738352 | controller |
2025-10-08 12:18:45.738385 | controller | TASK [virtualbmc : Start new host in VBMC] *************************************
2025-10-08 12:18:45.738394 | controller | Wednesday 08 October 2025  12:18:45 +0000 (0:00:00.695)       0:00:13.693 *****
2025-10-08 12:18:45.738404 | controller | changed: [instance]
2025-10-08 12:18:46.117157 | controller |
2025-10-08 12:18:46.117191 | controller | TASK [Stop VM using IPMI] ******************************************************
2025-10-08 12:18:46.117200 | controller | Wednesday 08 October 2025  12:18:45 +0000 (0:00:00.546)       0:00:14.240 *****
2025-10-08 12:18:46.117211 | controller | changed: [instance]
2025-10-08 12:18:46.439295 | controller |
2025-10-08 12:18:46.439330 | controller | TASK [List VMs from the hypervisor] ********************************************
2025-10-08 12:18:46.439338 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.378)       0:00:14.618 *****
2025-10-08 12:18:46.439348 | controller | ok: [instance]
2025-10-08 12:18:46.460346 | controller |
2025-10-08 12:18:46.460379 | controller | TASK [Ensure VM is stopped] ****************************************************
2025-10-08 12:18:46.460388 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.322)       0:00:14.941 *****
2025-10-08 12:18:46.460398 | controller | ok: [instance] => changed=false
2025-10-08 12:18:46.929711 | controller |   msg: All assertions passed
2025-10-08 12:18:46.929746 | controller |
2025-10-08 12:18:46.929754 | controller | TASK [virtualbmc : Get existing known VBMC nodes] ******************************
2025-10-08 12:18:46.929761 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.020)       0:00:14.962 *****
2025-10-08 12:18:46.929771 | controller | changed: [instance]
2025-10-08 12:18:46.955685 | controller |
2025-10-08 12:18:46.955722 | controller | TASK [virtualbmc : Expose known hosts] *****************************************
2025-10-08 12:18:46.955731 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.469)       0:00:15.431 *****
2025-10-08 12:18:46.955741 | controller | ok: [instance]
2025-10-08 12:18:46.984981 | controller |
2025-10-08 12:18:46.985016 | controller | TASK [Ensure we have the needed fact] ******************************************
2025-10-08 12:18:46.985025 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.025)       0:00:15.457 *****
2025-10-08 12:18:46.985036 | controller | ok: [instance] => changed=false
2025-10-08 12:18:47.005909 | controller |   msg: All assertions passed
2025-10-08 12:18:47.005981 | controller |
2025-10-08 12:18:47.005991 | controller | TASK [Expose known hosts] ******************************************************
2025-10-08 12:18:47.005998 | controller | Wednesday 08 October 2025  12:18:46 +0000 (0:00:00.029)       0:00:15.486 *****
2025-10-08 12:18:47.006011 | controller | ok: [instance] =>
2025-10-08 12:18:47.006046 | controller |   cifmw_virtualbmc_known_hosts:
2025-10-08 12:18:47.006053 | controller |   - Address: 127.0.0.1
2025-10-08 12:18:47.006059 | controller |     Domain name: cifmw-compute-0
2025-10-08 12:18:47.006065 | controller |     Port: 6241
2025-10-08 12:18:47.006070 | controller |     Status: running
2025-10-08 12:18:47.006083 | controller |
2025-10-08 12:18:47.006161 | controller | TASK [virtualbmc : Assert we have required data] *******************************
2025-10-08 12:18:47.006189 | controller | Wednesday 08 October 2025  12:18:47 +0000 (0:00:00.020)       0:00:15.507 *****
2025-10-08 12:18:47.033344 | controller | ok: [instance] => changed=false
2025-10-08 12:18:47.508870 | controller |   msg: All assertions passed
2025-10-08 12:18:47.508901 | controller |
2025-10-08 12:18:47.508909 | controller | TASK [virtualbmc : Get existing known VBMC nodes] ******************************
2025-10-08 12:18:47.508916 | controller | Wednesday 08 October 2025  12:18:47 +0000 (0:00:00.027)       0:00:15.535 *****
2025-10-08 12:18:47.508926 | controller | changed: [instance]
2025-10-08 12:18:47.509275 | controller |
2025-10-08 12:18:47.528882 | controller | TASK [virtualbmc : Expose known hosts] *****************************************
2025-10-08 12:18:47.528914 | controller | Wednesday 08 October 2025  12:18:47 +0000 (0:00:00.476)       0:00:16.011 *****
2025-10-08 12:18:47.528925 | controller | ok: [instance]
2025-10-08 12:18:47.529311 | controller |
2025-10-08 12:18:47.997343 | controller | TASK [virtualbmc : Stop host in VBMC] ******************************************
2025-10-08 12:18:47.997380 | controller | Wednesday 08 October 2025  12:18:47 +0000 (0:00:00.020)       0:00:16.031 *****
2025-10-08 12:18:47.997393 | controller | changed: [instance]
2025-10-08 12:18:48.469577 | controller |
2025-10-08 12:18:48.469612 | controller | TASK [virtualbmc : Add new host to VBMC] ***************************************
2025-10-08 12:18:48.469621 | controller | Wednesday 08 October 2025  12:18:47 +0000 (0:00:00.467)       0:00:16.498 *****
2025-10-08 12:18:48.469633 | controller | changed: [instance]
2025-10-08 12:18:48.505757 | controller |
2025-10-08 12:18:48.505789 | controller | TASK [virtualbmc : Start new host in VBMC] *************************************
2025-10-08 12:18:48.505797 | controller | Wednesday 08 October 2025  12:18:48 +0000 (0:00:00.472)       0:00:16.971 *****
2025-10-08 12:18:48.505831 | controller | skipping: [instance]
2025-10-08 12:18:48.965493 | controller |
2025-10-08 12:18:48.965524 | controller | TASK [virtualbmc : Get existing known VBMC nodes] ******************************
2025-10-08 12:18:48.965533 | controller | Wednesday 08 October 2025  12:18:48 +0000 (0:00:00.036)       0:00:17.007 *****
2025-10-08 12:18:48.965543 | controller | changed: [instance]
2025-10-08 12:18:48.990362 | controller |
2025-10-08 12:18:48.990392 | controller | TASK [virtualbmc : Expose known hosts] *****************************************
2025-10-08 12:18:48.990400 | controller | Wednesday 08 October 2025  12:18:48 +0000 (0:00:00.459)       0:00:17.467 *****
2025-10-08 12:18:48.990411 | controller | ok: [instance]
2025-10-08 12:18:49.030901 | controller |
2025-10-08 12:18:49.030975 | controller | TASK [Ensure we have the needed fact] ******************************************
2025-10-08 12:18:49.030986 | controller | Wednesday 08 October 2025  12:18:48 +0000 (0:00:00.024)       0:00:17.492 *****
2025-10-08 12:18:49.031001 | controller | ok: [instance] => changed=false
2025-10-08 12:18:49.031899 | controller |   msg: All assertions passed
2025-10-08 12:18:49.031948 | controller |
2025-10-08 12:18:49.031982 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:18:49.031990 | controller | instance                   : ok=32   changed=17   unreachable=0    failed=0    skipped=5    rescued=0    ignored=0
2025-10-08 12:18:49.031996 | controller |
2025-10-08 12:18:49.032001 | controller | Wednesday 08 October 2025  12:18:49 +0000 (0:00:00.040)       0:00:17.532 *****
2025-10-08 12:18:49.032007 | controller | ===============================================================================
2025-10-08 12:18:49.032013 | controller | virtualbmc : Pull vbmc container image ---------------------------------- 6.24s
2025-10-08 12:18:49.032021 | controller | podman : Ensure podman is installed ------------------------------------- 1.38s
2025-10-08 12:18:49.032028 | controller | Gathering Facts --------------------------------------------------------- 0.85s
2025-10-08 12:18:49.032175 | controller | virtualbmc : Create and start vbmc container ---------------------------- 0.74s
2025-10-08 12:18:49.032301 | controller | virtualbmc : Add new host to VBMC --------------------------------------- 0.70s
2025-10-08 12:18:49.032421 | controller | virtualbmc : Create ssh_config snippet for VBMC ------------------------- 0.56s
2025-10-08 12:18:49.032546 | controller | virtualbmc : Start new host in VBMC ------------------------------------- 0.55s
2025-10-08 12:18:49.032985 | controller | virtualbmc : Get existing known VBMC nodes ------------------------------ 0.49s
2025-10-08 12:18:49.033139 | controller | virtualbmc : Get existing known VBMC nodes ------------------------------ 0.48s
2025-10-08 12:18:49.033257 | controller | virtualbmc : Add new host to VBMC --------------------------------------- 0.47s
2025-10-08 12:18:49.033376 | controller | virtualbmc : Get existing known VBMC nodes ------------------------------ 0.47s
2025-10-08 12:18:49.033492 | controller | virtualbmc : Stop host in VBMC ------------------------------------------ 0.47s
2025-10-08 12:18:49.033610 | controller | virtualbmc : Get existing known VBMC nodes ------------------------------ 0.46s
2025-10-08 12:18:49.033720 | controller | virtualbmc : Check if container already exists -------------------------- 0.44s
2025-10-08 12:18:49.033859 | controller | virtualbmc : Allow VBMC temporary key ----------------------------------- 0.39s
2025-10-08 12:18:49.034000 | controller | virtualbmc : Create ssh key for VBMC ------------------------------------ 0.38s
2025-10-08 12:18:49.034114 | controller | Stop VM using IPMI ------------------------------------------------------ 0.38s
2025-10-08 12:18:49.034229 | controller | virtualbmc : Create vbmc server configuration file ---------------------- 0.36s
2025-10-08 12:18:49.034341 | controller | virtualbmc : Create undying vbmcd service script ------------------------ 0.36s
2025-10-08 12:18:49.034455 | controller | podman : Enable loginctl linger for ansible_user_id --------------------- 0.32s
2025-10-08 12:18:49.093907 | controller | INFO     Running default > cleanup
2025-10-08 12:18:49.612902 | controller |
2025-10-08 12:18:49.613074 | controller | PLAY [Cleanup] *****************************************************************
2025-10-08 12:18:49.613193 | controller |
2025-10-08 12:18:49.613325 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:18:49.613465 | controller | Wednesday 08 October 2025  12:18:49 +0000 (0:00:00.017)       0:00:00.017 *****
2025-10-08 12:18:50.478835 | controller | ok: [instance]
2025-10-08 12:18:51.304843 | controller |
2025-10-08 12:18:51.304878 | controller | TASK [libvirt_manager : Get installed packages list] ***************************
2025-10-08 12:18:51.304886 | controller | Wednesday 08 October 2025  12:18:50 +0000 (0:00:00.865)       0:00:00.882 *****
2025-10-08 12:18:51.304897 | controller | ok: [instance]
2025-10-08 12:18:53.716067 | controller |
2025-10-08 12:18:53.716112 | controller | TASK [libvirt_manager : Populate service facts] ********************************
2025-10-08 12:18:53.716121 | controller | Wednesday 08 October 2025  12:18:51 +0000 (0:00:00.825)       0:00:01.708 *****
2025-10-08 12:18:53.716133 | controller | ok: [instance]
2025-10-08 12:18:54.661533 | controller |
2025-10-08 12:18:54.661569 | controller | TASK [libvirt_manager : Start virtqemud socket service] ************************
2025-10-08 12:18:54.661580 | controller | Wednesday 08 October 2025  12:18:53 +0000 (0:00:02.411)       0:00:04.120 *****
2025-10-08 12:18:54.661591 | controller | ok: [instance] => (item=virtqemud.service)
2025-10-08 12:18:54.716492 | controller | ok: [instance] => (item=virtqemud.socket)
2025-10-08 12:18:54.716524 | controller |
2025-10-08 12:18:54.716532 | controller | TASK [libvirt_manager : Set _is_deepscrub internal fact] ***********************
2025-10-08 12:18:54.716538 | controller | Wednesday 08 October 2025  12:18:54 +0000 (0:00:00.945)       0:00:05.065 *****
2025-10-08 12:18:54.716548 | controller | ok: [instance]
2025-10-08 12:18:55.125572 | controller |
2025-10-08 12:18:55.125606 | controller | TASK [libvirt_manager : List all of the existing virtual machines] *************
2025-10-08 12:18:55.125615 | controller | Wednesday 08 October 2025  12:18:54 +0000 (0:00:00.055)       0:00:05.120 *****
2025-10-08 12:18:55.125625 | controller | ok: [instance]
2025-10-08 12:18:55.535936 | controller |
2025-10-08 12:18:55.536124 | controller | TASK [libvirt_manager : Get pool configuration] ********************************
2025-10-08 12:18:55.536210 | controller | Wednesday 08 October 2025  12:18:55 +0000 (0:00:00.408)       0:00:05.529 *****
2025-10-08 12:18:55.536236 | controller | ok: [instance]
2025-10-08 12:18:55.667035 | controller |
2025-10-08 12:18:55.667101 | controller | TASK [libvirt_manager : Filter out target environment] *************************
2025-10-08 12:18:55.667111 | controller | Wednesday 08 October 2025  12:18:55 +0000 (0:00:00.410)       0:00:05.940 *****
2025-10-08 12:18:55.667125 | controller | ok: [instance]
2025-10-08 12:18:55.755821 | controller |
2025-10-08 12:18:55.755859 | controller | TASK [libvirt_manager : Expose cleanup list] ***********************************
2025-10-08 12:18:55.755868 | controller | Wednesday 08 October 2025  12:18:55 +0000 (0:00:00.130)       0:00:06.071 *****
2025-10-08 12:18:55.755879 | controller | ok: [instance] =>
2025-10-08 12:18:56.130501 | controller |   cleanup_vms:
2025-10-08 12:18:56.130546 | controller |   - cifmw-compute-0
2025-10-08 12:18:56.130554 | controller |
2025-10-08 12:18:56.130561 | controller | TASK [libvirt_manager : Clean ssh known_hosts] *********************************
2025-10-08 12:18:56.130567 | controller | Wednesday 08 October 2025  12:18:55 +0000 (0:00:00.088)       0:00:06.159 *****
2025-10-08 12:18:56.130576 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-08 12:18:56.459429 | controller |
2025-10-08 12:18:56.459466 | controller | TASK [libvirt_manager : Destroy machine] ***************************************
2025-10-08 12:18:56.459475 | controller | Wednesday 08 October 2025  12:18:56 +0000 (0:00:00.374)       0:00:06.534 *****
2025-10-08 12:18:56.459490 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-08 12:18:56.785433 | controller |
2025-10-08 12:18:56.785470 | controller | TASK [libvirt_manager : Undefine machine] **************************************
2025-10-08 12:18:56.785478 | controller | Wednesday 08 October 2025  12:18:56 +0000 (0:00:00.329)       0:00:06.863 *****
2025-10-08 12:18:56.785489 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-08 12:18:57.171532 | controller |
2025-10-08 12:18:57.171569 | controller | TASK [libvirt_manager : (localhost) Clean ssh jumpers] *************************
2025-10-08 12:18:57.171577 | controller | Wednesday 08 October 2025  12:18:56 +0000 (0:00:00.326)       0:00:07.189 *****
2025-10-08 12:18:57.171588 | controller | ok: [instance -> localhost] => (item=cifmw-compute-0)
2025-10-08 12:18:57.445967 | controller |
2025-10-08 12:18:57.446006 | controller | TASK [libvirt_manager : (instance) Clean ssh jumpers] **************************
2025-10-08 12:18:57.446016 | controller | Wednesday 08 October 2025  12:18:57 +0000 (0:00:00.386)       0:00:07.575 *****
2025-10-08 12:18:57.446028 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-08 12:18:57.446071 | controller |
2025-10-08 12:18:57.446079 | controller | TASK [libvirt_manager : Get network list] **************************************
2025-10-08 12:18:57.446086 | controller | Wednesday 08 October 2025  12:18:57 +0000 (0:00:00.274)       0:00:07.849 *****
2025-10-08 12:18:57.846945 | controller | ok: [instance]
2025-10-08 12:18:57.847022 | controller |
2025-10-08 12:18:57.847257 | controller | TASK [libvirt_manager : Filter out target nets] ********************************
2025-10-08 12:18:57.943858 | controller | Wednesday 08 October 2025  12:18:57 +0000 (0:00:00.401)       0:00:08.251 *****
2025-10-08 12:18:57.943899 | controller | ok: [instance]
2025-10-08 12:18:58.028676 | controller |
2025-10-08 12:18:58.028711 | controller | TASK [libvirt_manager : Expose cleanup list] ***********************************
2025-10-08 12:18:58.028719 | controller | Wednesday 08 October 2025  12:18:57 +0000 (0:00:00.096)       0:00:08.347 *****
2025-10-08 12:18:58.028730 | controller | ok: [instance] =>
2025-10-08 12:18:58.173693 | controller |   cleanup_nets:
2025-10-08 12:18:58.173734 | controller |   - cifmw-public
2025-10-08 12:18:58.173748 | controller |
2025-10-08 12:18:58.173757 | controller | TASK [Remove dnsmasq network bits] *********************************************
2025-10-08 12:18:58.173765 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.084)       0:00:08.432 *****
2025-10-08 12:18:58.173777 | controller |
2025-10-08 12:18:58.174043 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************
2025-10-08 12:18:58.174229 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.145)       0:00:08.577 *****
2025-10-08 12:18:58.257705 | controller | ok: [instance] => changed=false
2025-10-08 12:18:58.257990 | controller |   msg: All assertions passed
2025-10-08 12:18:58.258150 | controller |
2025-10-08 12:18:58.258304 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] *******************
2025-10-08 12:18:58.258446 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.084)       0:00:08.662 *****
2025-10-08 12:18:58.338408 | controller | skipping: [instance]
2025-10-08 12:18:58.338596 | controller |
2025-10-08 12:18:58.338746 | controller | TASK [dnsmasq : Create network] ************************************************
2025-10-08 12:18:58.338976 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.080)       0:00:08.742 *****
2025-10-08 12:18:58.420379 | controller | skipping: [instance]
2025-10-08 12:18:58.420570 | controller |
2025-10-08 12:18:58.420720 | controller | TASK [dnsmasq : Remove network] ************************************************
2025-10-08 12:18:58.420897 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.081)       0:00:08.824 *****
2025-10-08 12:18:58.832317 | controller | ok: [instance]
2025-10-08 12:18:59.140994 | controller |
2025-10-08 12:18:59.141038 | controller | TASK [dnsmasq : Remove dhcp host files] ****************************************
2025-10-08 12:18:59.141046 | controller | Wednesday 08 October 2025  12:18:58 +0000 (0:00:00.411)       0:00:09.236 *****
2025-10-08 12:18:59.141059 | controller | ok: [instance]
2025-10-08 12:18:59.141084 | controller |
2025-10-08 12:18:59.141091 | controller | TASK [libvirt_manager : Destroy networks] **************************************
2025-10-08 12:18:59.141098 | controller | Wednesday 08 October 2025  12:18:59 +0000 (0:00:00.308)       0:00:09.544 *****
2025-10-08 12:18:59.797983 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:18:59.798285 | controller |
2025-10-08 12:19:00.133555 | controller | TASK [libvirt_manager : Undefine networks] *************************************
2025-10-08 12:19:00.133593 | controller | Wednesday 08 October 2025  12:18:59 +0000 (0:00:00.657)       0:00:10.202 *****
2025-10-08 12:19:00.133605 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:19:00.594121 | controller |
2025-10-08 12:19:00.594168 | controller | TASK [libvirt_manager : Ensure no trace of networks lays in nmcli] *************
2025-10-08 12:19:00.594179 | controller | Wednesday 08 October 2025  12:19:00 +0000 (0:00:00.335)       0:00:10.537 *****
2025-10-08 12:19:00.594193 | controller | ok: [instance] => (item=cifmw-public)
2025-10-08 12:19:00.594268 | controller |
2025-10-08 12:19:00.594306 | controller | TASK [libvirt_manager : Find dummy interface connection files] *****************
2025-10-08 12:19:00.983987 | controller | Wednesday 08 October 2025  12:19:00 +0000 (0:00:00.460)       0:00:10.997 *****
2025-10-08 12:19:00.984044 | controller | ok: [instance]
2025-10-08 12:19:00.984066 | controller |
2025-10-08 12:19:00.984075 | controller | TASK [libvirt_manager : Remove dummy interface connections] ********************
2025-10-08 12:19:00.984214 | controller | Wednesday 08 October 2025  12:19:00 +0000 (0:00:00.390)       0:00:11.388 *****
2025-10-08 12:19:01.287998 | controller | changed: [instance] => (item={'path': '/etc/NetworkManager/system-connections/dummy-zoorn5o4.nmconnection', 'mode': '0600', 'isdir': False, 'ischr': False, 'isblk': False, 'isreg': True, 'isfifo': False, 'islnk': False, 'issock': False, 'uid': 0, 'gid': 0, 'size': 308, 'inode': 1433973, 'dev': 64513, 'nlink': 1, 'atime': 1759925884.256308, 'mtime': 1759925884.256308, 'ctime': 1759925884.257308, 'gr_name': 'root', 'pw_name': 'root', 'wusr': True, 'rusr': True, 'xusr': False, 'wgrp': False, 'rgrp': False, 'xgrp': False, 'woth': False, 'roth': False, 'xoth': False, 'isuid': False, 'isgid': False})
2025-10-08 12:19:01.288041 | controller |
2025-10-08 12:19:01.288051 | controller | TASK [libvirt_manager : Clean firewalld libvirt zone] **************************
2025-10-08 12:19:01.288062 | controller | Wednesday 08 October 2025  12:19:01 +0000 (0:00:00.303)       0:00:11.692 *****
2025-10-08 12:19:01.846932 | controller | changed: [instance] => (item=cifmw-public)
2025-10-08 12:19:01.847000 | controller |
2025-10-08 12:19:01.847017 | controller | TASK [libvirt_manager : Disable masquerade in firewalld default zone] **********
2025-10-08 12:19:01.847028 | controller | Wednesday 08 October 2025  12:19:01 +0000 (0:00:00.559)       0:00:12.251 *****
2025-10-08 12:19:02.252763 | controller | changed: [instance]
2025-10-08 12:19:02.843023 | controller |
2025-10-08 12:19:02.843080 | controller | TASK [libvirt_manager : Disable forward in firewalld libvirt zone] *************
2025-10-08 12:19:02.843089 | controller | Wednesday 08 October 2025  12:19:02 +0000 (0:00:00.405)       0:00:12.656 *****
2025-10-08 12:19:02.843100 | controller | changed: [instance]
2025-10-08 12:19:02.982685 | controller |
2025-10-08 12:19:02.982722 | controller | TASK [libvirt_manager : Remove cifmw storage pool] *****************************
2025-10-08 12:19:02.982730 | controller | Wednesday 08 October 2025  12:19:02 +0000 (0:00:00.590)       0:00:13.246 *****
2025-10-08 12:19:02.982747 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/storage_pool.yml for instance
2025-10-08 12:19:03.066908 | controller |
2025-10-08 12:19:03.066944 | controller | TASK [libvirt_manager : Ensure we have a known action] *************************
2025-10-08 12:19:03.066970 | controller | Wednesday 08 October 2025  12:19:02 +0000 (0:00:00.139)       0:00:13.386 *****
2025-10-08 12:19:03.066981 | controller | ok: [instance] => changed=false
2025-10-08 12:19:03.352538 | controller |   msg: All assertions passed
2025-10-08 12:19:03.352575 | controller |
2025-10-08 12:19:03.352584 | controller | TASK [libvirt_manager : Gather the status of cifmw-pool storage pool.] *********
2025-10-08 12:19:03.352590 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.083)       0:00:13.470 *****
2025-10-08 12:19:03.352600 | controller | changed: [instance]
2025-10-08 12:19:03.435526 | controller |
2025-10-08 12:19:03.435559 | controller | TASK [libvirt_manager : Create the storage pool] *******************************
2025-10-08 12:19:03.435567 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.285)       0:00:13.756 *****
2025-10-08 12:19:03.435577 | controller | skipping: [instance]
2025-10-08 12:19:03.552021 | controller |
2025-10-08 12:19:03.552067 | controller | TASK [libvirt_manager : Ensure the storage pool is started] ********************
2025-10-08 12:19:03.552075 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.083)       0:00:13.839 *****
2025-10-08 12:19:03.552086 | controller | skipping: [instance] => (item=pool-start)
2025-10-08 12:19:03.552147 | controller | skipping: [instance] => (item=pool-autostart)
2025-10-08 12:19:03.552178 | controller | skipping: [instance]
2025-10-08 12:19:03.552186 | controller |
2025-10-08 12:19:03.552193 | controller | TASK [libvirt_manager : Gather all the volumes in the pool to delete] **********
2025-10-08 12:19:03.552203 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.116)       0:00:13.956 *****
2025-10-08 12:19:03.638533 | controller | skipping: [instance]
2025-10-08 12:19:03.723847 | controller |
2025-10-08 12:19:03.723893 | controller | TASK [libvirt_manager : Remove the volumes from pool to delete] ****************
2025-10-08 12:19:03.723902 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.086)       0:00:14.042 *****
2025-10-08 12:19:03.723912 | controller | skipping: [instance]
2025-10-08 12:19:03.843459 | controller |
2025-10-08 12:19:03.843493 | controller | TASK [libvirt_manager : Delete storage pool] ***********************************
2025-10-08 12:19:03.843501 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.085)       0:00:14.127 *****
2025-10-08 12:19:03.843512 | controller | skipping: [instance] => (item=pool-destroy)
2025-10-08 12:19:04.155155 | controller | skipping: [instance] => (item=pool-undefine)
2025-10-08 12:19:04.155188 | controller | skipping: [instance]
2025-10-08 12:19:04.155197 | controller |
2025-10-08 12:19:04.155203 | controller | TASK [libvirt_manager : Refresh pools facts] ***********************************
2025-10-08 12:19:04.155209 | controller | Wednesday 08 October 2025  12:19:03 +0000 (0:00:00.119)       0:00:14.247 *****
2025-10-08 12:19:04.155219 | controller | ok: [instance]
2025-10-08 12:19:04.245885 | controller |
2025-10-08 12:19:04.245921 | controller | TASK [libvirt_manager : Remove overlay images from ocp_volume pools if exists] ***
2025-10-08 12:19:04.245929 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.312)       0:00:14.559 *****
2025-10-08 12:19:04.245940 | controller | skipping: [instance]
2025-10-08 12:19:04.329311 | controller |
2025-10-08 12:19:04.329346 | controller | TASK [libvirt_manager : Remove ocp_volumes storage pool] ***********************
2025-10-08 12:19:04.329355 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.090)       0:00:14.649 *****
2025-10-08 12:19:04.329371 | controller | skipping: [instance]
2025-10-08 12:19:04.379000 | controller |
2025-10-08 12:19:04.379041 | controller | TASK [libvirt_manager : Refresh all pools after actions] ***********************
2025-10-08 12:19:04.379051 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.083)       0:00:14.733 *****
2025-10-08 12:19:04.379064 | controller | skipping: [instance]
2025-10-08 12:19:04.676792 | controller |
2025-10-08 12:19:04.676842 | controller | TASK [libvirt_manager : Get temporary key status] ******************************
2025-10-08 12:19:04.676851 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.049)       0:00:14.782 *****
2025-10-08 12:19:04.676861 | controller | ok: [instance]
2025-10-08 12:19:04.726908 | controller |
2025-10-08 12:19:04.726973 | controller | TASK [libvirt_manager : Get public key] ****************************************
2025-10-08 12:19:04.727002 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.297)       0:00:15.080 *****
2025-10-08 12:19:04.727017 | controller | skipping: [instance]
2025-10-08 12:19:04.777363 | controller |
2025-10-08 12:19:04.777399 | controller | TASK [libvirt_manager : Remove public key] *************************************
2025-10-08 12:19:04.777407 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.050)       0:00:15.130 *****
2025-10-08 12:19:04.777418 | controller | skipping: [instance]
2025-10-08 12:19:04.835006 | controller |
2025-10-08 12:19:04.835050 | controller | TASK [libvirt_manager : Remove keypair] ****************************************
2025-10-08 12:19:04.835061 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.050)       0:00:15.181 *****
2025-10-08 12:19:04.835074 | controller | skipping: [instance] => (item=cifmw_reproducer_key.pub)
2025-10-08 12:19:05.059964 | controller | skipping: [instance] => (item=cifmw_reproducer_key)
2025-10-08 12:19:05.059999 | controller | skipping: [instance]
2025-10-08 12:19:05.060007 | controller |
2025-10-08 12:19:05.060013 | controller | TASK [libvirt_manager : List libvirt logs] *************************************
2025-10-08 12:19:05.060019 | controller | Wednesday 08 October 2025  12:19:04 +0000 (0:00:00.057)       0:00:15.238 *****
2025-10-08 12:19:05.060029 | controller | ok: [instance]
2025-10-08 12:19:05.060056 | controller |
2025-10-08 12:19:05.060064 | controller | TASK [libvirt_manager : Remove detected logs] **********************************
2025-10-08 12:19:05.060206 | controller | Wednesday 08 October 2025  12:19:05 +0000 (0:00:00.225)       0:00:15.464 *****
2025-10-08 12:19:05.098997 | controller | skipping: [instance]
2025-10-08 12:19:05.099185 | controller |
2025-10-08 12:19:05.099204 | controller | TASK [libvirt_manager : Remove workload and volumes] ***************************
2025-10-08 12:19:06.537968 | controller | Wednesday 08 October 2025  12:19:05 +0000 (0:00:00.039)       0:00:15.503 *****
2025-10-08 12:19:06.538019 | controller | changed: [instance] => (item=workload)
2025-10-08 12:19:06.590939 | controller | changed: [instance] => (item=volumes)
2025-10-08 12:19:06.590996 | controller | changed: [instance] => (item=artifacts/debug_network_data.yml)
2025-10-08 12:19:06.591006 | controller | changed: [instance] => (item=artifacts/debug_pub_net_value.txt)
2025-10-08 12:19:06.591013 | controller | changed: [instance] => (item=artifacts/debug_cifmw_libvirt_manager_layout.yml)
2025-10-08 12:19:06.591020 | controller | changed: [instance] => (item=artifacts/interfaces-info.yml)
2025-10-08 12:19:06.591027 | controller | changed: [instance] => (item=artifacts/libvirt-uuids.yml)
2025-10-08 12:19:06.591034 | controller | changed: [instance] => (item=artifacts/net-map-def-patch.yml)
2025-10-08 12:19:06.591041 | controller |
2025-10-08 12:19:06.591048 | controller | TASK [libvirt_manager : Deepscrub data] ****************************************
2025-10-08 12:19:06.591055 | controller | Wednesday 08 October 2025  12:19:06 +0000 (0:00:01.437)       0:00:16.941 *****
2025-10-08 12:19:06.591067 | controller | skipping: [instance] => (item=images)
2025-10-08 12:19:07.982031 | controller | skipping: [instance] => (item=artifacts/virtual-nodes.yml)
2025-10-08 12:19:07.982099 | controller | skipping: [instance]
2025-10-08 12:19:07.982108 | controller |
2025-10-08 12:19:07.982114 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-10-08 12:19:07.982120 | controller | Wednesday 08 October 2025  12:19:06 +0000 (0:00:00.053)       0:00:16.994 *****
2025-10-08 12:19:07.982134 | controller | ok: [instance]
2025-10-08 12:19:07.982141 | controller |
2025-10-08 12:19:07.982149 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-10-08 12:19:08.290022 | controller | Wednesday 08 October 2025  12:19:07 +0000 (0:00:01.391)       0:00:18.386 *****
2025-10-08 12:19:08.290062 | controller | changed: [instance]
2025-10-08 12:19:08.290097 | controller |
2025-10-08 12:19:08.290107 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-10-08 12:19:08.290116 | controller | Wednesday 08 October 2025  12:19:08 +0000 (0:00:00.308)       0:00:18.694 *****
2025-10-08 12:19:08.341579 | controller | skipping: [instance]
2025-10-08 12:19:08.389750 | controller |
2025-10-08 12:19:08.389786 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-10-08 12:19:08.389796 | controller | Wednesday 08 October 2025  12:19:08 +0000 (0:00:00.051)       0:00:18.745 *****
2025-10-08 12:19:08.389830 | controller | skipping: [instance]
2025-10-08 12:19:08.461836 | controller |
2025-10-08 12:19:08.461879 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-10-08 12:19:08.461889 | controller | Wednesday 08 October 2025  12:19:08 +0000 (0:00:00.048)       0:00:18.793 *****
2025-10-08 12:19:08.461901 | controller | skipping: [instance]
2025-10-08 12:19:19.097714 | controller |
2025-10-08 12:19:19.097751 | controller | TASK [virtualbmc : Stop and remove vbmc container] *****************************
2025-10-08 12:19:19.097759 | controller | Wednesday 08 October 2025  12:19:08 +0000 (0:00:00.071)       0:00:18.865 *****
2025-10-08 12:19:19.097770 | controller | changed: [instance]
2025-10-08 12:19:20.337998 | controller |
2025-10-08 12:19:20.338040 | controller | TASK [virtualbmc : Remove vbmc container image] ********************************
2025-10-08 12:19:20.338056 | controller | Wednesday 08 October 2025  12:19:19 +0000 (0:00:10.636)       0:00:29.501 *****
2025-10-08 12:19:20.338067 | controller | changed: [instance]
2025-10-08 12:19:20.338097 | controller |
2025-10-08 12:19:20.338105 | controller | TASK [virtualbmc : Check if VBMC key exists] ***********************************
2025-10-08 12:19:20.338273 | controller | Wednesday 08 October 2025  12:19:20 +0000 (0:00:01.240)       0:00:30.742 *****
2025-10-08 12:19:20.599465 | controller | ok: [instance]
2025-10-08 12:19:20.908767 | controller |
2025-10-08 12:19:20.908824 | controller | TASK [virtualbmc : Slurp key] **************************************************
2025-10-08 12:19:20.908836 | controller | Wednesday 08 October 2025  12:19:20 +0000 (0:00:00.261)       0:00:31.003 *****
2025-10-08 12:19:20.908847 | controller | ok: [instance]
2025-10-08 12:19:21.305479 | controller |
2025-10-08 12:19:21.305514 | controller | TASK [virtualbmc : Revoke VBMC SSH access] *************************************
2025-10-08 12:19:21.305522 | controller | Wednesday 08 October 2025  12:19:20 +0000 (0:00:00.309)       0:00:31.312 *****
2025-10-08 12:19:21.305532 | controller | changed: [instance]
2025-10-08 12:19:22.082088 | controller |
2025-10-08 12:19:22.082138 | controller | TASK [virtualbmc : Remove vbmc files] ******************************************
2025-10-08 12:19:22.082148 | controller | Wednesday 08 October 2025  12:19:21 +0000 (0:00:00.396)       0:00:31.709 *****
2025-10-08 12:19:22.082162 | controller | changed: [instance] => (item=/home/zuul/.ssh/vbmc-key)
2025-10-08 12:19:22.082184 | controller | changed: [instance] => (item=/home/zuul/.ssh/vbmc-key.pub)
2025-10-08 12:19:22.082194 | controller | changed: [instance] => (item=/home/zuul/.ssh/virtualbmc.conf)
2025-10-08 12:19:22.082507 | controller | changed: [instance] => (item=/home/zuul/.ssh/vbmcd.sh)
2025-10-08 12:19:22.082542 | controller |
2025-10-08 12:19:22.169226 | controller | TASK [Clean remote ssh config] *************************************************
2025-10-08 12:19:22.169262 | controller | Wednesday 08 October 2025  12:19:22 +0000 (0:00:00.776)       0:00:32.486 *****
2025-10-08 12:19:22.169274 | controller |
2025-10-08 12:19:22.531350 | controller | TASK [ssh_jumper : Remove Include cifmw_ssh_config.d] **************************
2025-10-08 12:19:22.531386 | controller | Wednesday 08 October 2025  12:19:22 +0000 (0:00:00.086)       0:00:32.573 *****
2025-10-08 12:19:22.531398 | controller | ok: [instance]
2025-10-08 12:19:22.783342 | controller |
2025-10-08 12:19:22.783376 | controller | TASK [ssh_jumper : Remove cifmw_ssh_config.d directory] ************************
2025-10-08 12:19:22.783385 | controller | Wednesday 08 October 2025  12:19:22 +0000 (0:00:00.362)       0:00:32.935 *****
2025-10-08 12:19:22.783395 | controller | ok: [instance]
2025-10-08 12:19:22.870363 | controller |
2025-10-08 12:19:22.870397 | controller | TASK [Clean local ssh config] **************************************************
2025-10-08 12:19:22.870405 | controller | Wednesday 08 October 2025  12:19:22 +0000 (0:00:00.251)       0:00:33.187 *****
2025-10-08 12:19:22.870415 | controller |
2025-10-08 12:19:23.097606 | controller | TASK [ssh_jumper : Remove Include cifmw_ssh_config.d] **************************
2025-10-08 12:19:23.097655 | controller | Wednesday 08 October 2025  12:19:22 +0000 (0:00:00.087)       0:00:33.274 *****
2025-10-08 12:19:23.097669 | controller | ok: [instance -> localhost]
2025-10-08 12:19:23.354477 | controller |
2025-10-08 12:19:23.354517 | controller | TASK [ssh_jumper : Remove cifmw_ssh_config.d directory] ************************
2025-10-08 12:19:23.354526 | controller | Wednesday 08 October 2025  12:19:23 +0000 (0:00:00.226)       0:00:33.501 *****
2025-10-08 12:19:23.354536 | controller | ok: [instance -> localhost]
2025-10-08 12:19:23.430235 | controller |
2025-10-08 12:19:23.430277 | controller | TASK [dnsmasq : Cleaning dnsmasq] **********************************************
2025-10-08 12:19:23.430287 | controller | Wednesday 08 October 2025  12:19:23 +0000 (0:00:00.256)       0:00:33.758 *****
2025-10-08 12:19:23.430300 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/configure.yml for instance
2025-10-08 12:19:24.768941 | controller |
2025-10-08 12:19:24.769000 | controller | TASK [dnsmasq : Install needed packages] ***************************************
2025-10-08 12:19:24.769008 | controller | Wednesday 08 October 2025  12:19:23 +0000 (0:00:00.075)       0:00:33.833 *****
2025-10-08 12:19:24.769020 | controller | ok: [instance]
2025-10-08 12:19:24.769076 | controller |
2025-10-08 12:19:24.769107 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ******
2025-10-08 12:19:24.769119 | controller | Wednesday 08 October 2025  12:19:24 +0000 (0:00:01.339)       0:00:35.173 *****
2025-10-08 12:19:28.337954 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'})
2025-10-08 12:19:28.579914 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'})
2025-10-08 12:19:28.579946 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'})
2025-10-08 12:19:28.579954 | controller |
2025-10-08 12:19:28.579983 | controller | TASK [dnsmasq : Manage configuration directory] ********************************
2025-10-08 12:19:28.579989 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:03.568)       0:00:38.741 *****
2025-10-08 12:19:28.579999 | controller | changed: [instance]
2025-10-08 12:19:28.580017 | controller |
2025-10-08 12:19:28.580223 | controller | TASK [dnsmasq : Manage systemd unit file] **************************************
2025-10-08 12:19:28.640384 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:00.242)       0:00:38.984 *****
2025-10-08 12:19:28.640425 | controller | skipping: [instance]
2025-10-08 12:19:28.681700 | controller |
2025-10-08 12:19:28.681735 | controller | TASK [dnsmasq : Manage base configuration file] ********************************
2025-10-08 12:19:28.681744 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:00.060)       0:00:39.044 *****
2025-10-08 12:19:28.681754 | controller | skipping: [instance]
2025-10-08 12:19:28.749494 | controller |
2025-10-08 12:19:28.749529 | controller | TASK [dnsmasq : Render listener configuration] *********************************
2025-10-08 12:19:28.749537 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:00.041)       0:00:39.085 *****
2025-10-08 12:19:28.749548 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance
2025-10-08 12:19:28.788253 | controller |
2025-10-08 12:19:28.788285 | controller | TASK [dnsmasq : Create listener configuration file] ****************************
2025-10-08 12:19:28.788295 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:00.067)       0:00:39.153 *****
2025-10-08 12:19:28.788306 | controller | skipping: [instance]
2025-10-08 12:19:28.788480 | controller |
2025-10-08 12:19:28.788628 | controller | TASK [dnsmasq : Remove listener configuration file] ****************************
2025-10-08 12:19:28.788772 | controller | Wednesday 08 October 2025  12:19:28 +0000 (0:00:00.039)       0:00:39.192 *****
2025-10-08 12:19:29.023598 | controller | changed: [instance]
2025-10-08 12:19:29.093011 | controller |
2025-10-08 12:19:29.093056 | controller | TASK [dnsmasq : Render dns configuration] **************************************
2025-10-08 12:19:29.093065 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.234)       0:00:39.427 *****
2025-10-08 12:19:29.093076 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance
2025-10-08 12:19:29.133055 | controller |
2025-10-08 12:19:29.133105 | controller | TASK [dnsmasq : Create dns configuration file] *********************************
2025-10-08 12:19:29.133115 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.069)       0:00:39.496 *****
2025-10-08 12:19:29.133127 | controller | skipping: [instance]
2025-10-08 12:19:29.133162 | controller |
2025-10-08 12:19:29.133171 | controller | TASK [dnsmasq : Remove dns configuration file] *********************************
2025-10-08 12:19:29.133194 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.040)       0:00:39.537 *****
2025-10-08 12:19:29.366938 | controller | changed: [instance]
2025-10-08 12:19:29.434677 | controller |
2025-10-08 12:19:29.434713 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] ***
2025-10-08 12:19:29.434721 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.233)       0:00:39.770 *****
2025-10-08 12:19:29.434732 | controller | skipping: [instance]
2025-10-08 12:19:29.476899 | controller |
2025-10-08 12:19:29.476932 | controller | TASK [dnsmasq : Enable and start service] **************************************
2025-10-08 12:19:29.476940 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.067)       0:00:39.838 *****
2025-10-08 12:19:29.476950 | controller | skipping: [instance]
2025-10-08 12:19:30.277914 | controller |
2025-10-08 12:19:30.277947 | controller | TASK [dnsmasq : Stop service] **************************************************
2025-10-08 12:19:30.277955 | controller | Wednesday 08 October 2025  12:19:29 +0000 (0:00:00.042)       0:00:39.880 *****
2025-10-08 12:19:30.277986 | controller | changed: [instance]
2025-10-08 12:19:30.278152 | controller |
2025-10-08 12:19:30.278172 | controller | TASK [dnsmasq : Remove unit file] **********************************************
2025-10-08 12:19:30.500255 | controller | Wednesday 08 October 2025  12:19:30 +0000 (0:00:00.801)       0:00:40.682 *****
2025-10-08 12:19:30.500292 | controller | changed: [instance]
2025-10-08 12:19:30.912554 | controller |
2025-10-08 12:19:30.912590 | controller | TASK [dnsmasq : Remove main configuration files] *******************************
2025-10-08 12:19:30.912598 | controller | Wednesday 08 October 2025  12:19:30 +0000 (0:00:00.221)       0:00:40.904 *****
2025-10-08 12:19:30.912608 | controller | changed: [instance] => (item=/etc/cifmw-dnsmasq.conf)
2025-10-08 12:19:31.206274 | controller | changed: [instance] => (item=/etc/cifmw-dnsmasq.d)
2025-10-08 12:19:31.206309 | controller |
2025-10-08 12:19:31.206316 | controller | TASK [dnsmasq : Remove lease file] *********************************************
2025-10-08 12:19:31.206323 | controller | Wednesday 08 October 2025  12:19:30 +0000 (0:00:00.411)       0:00:41.316 *****
2025-10-08 12:19:31.206333 | controller | changed: [instance]
2025-10-08 12:19:32.514326 | controller |
2025-10-08 12:19:32.514359 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-10-08 12:19:32.514367 | controller | Wednesday 08 October 2025  12:19:31 +0000 (0:00:00.293)       0:00:41.609 *****
2025-10-08 12:19:32.514377 | controller | ok: [instance]
2025-10-08 12:19:32.768442 | controller |
2025-10-08 12:19:32.768473 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-10-08 12:19:32.768481 | controller | Wednesday 08 October 2025  12:19:32 +0000 (0:00:01.308)       0:00:42.918 *****
2025-10-08 12:19:32.768491 | controller | changed: [instance]
2025-10-08 12:19:32.816460 | controller |
2025-10-08 12:19:32.816491 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-10-08 12:19:32.816503 | controller | Wednesday 08 October 2025  12:19:32 +0000 (0:00:00.254)       0:00:43.172 *****
2025-10-08 12:19:32.816514 | controller | skipping: [instance]
2025-10-08 12:19:32.862039 | controller |
2025-10-08 12:19:32.862087 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-10-08 12:19:32.862097 | controller | Wednesday 08 October 2025  12:19:32 +0000 (0:00:00.048)       0:00:43.220 *****
2025-10-08 12:19:32.862110 | controller | skipping: [instance]
2025-10-08 12:19:32.862148 | controller |
2025-10-08 12:19:32.862158 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-10-08 12:19:32.931388 | controller | Wednesday 08 October 2025  12:19:32 +0000 (0:00:00.045)       0:00:43.266 *****
2025-10-08 12:19:32.931426 | controller | skipping: [instance]
2025-10-08 12:19:33.292404 | controller |
2025-10-08 12:19:33.292436 | controller | TASK [virtualbmc : Stop and remove vbmc container] *****************************
2025-10-08 12:19:33.292444 | controller | Wednesday 08 October 2025  12:19:32 +0000 (0:00:00.069)       0:00:43.335 *****
2025-10-08 12:19:33.292454 | controller | ok: [instance]
2025-10-08 12:19:33.598879 | controller |
2025-10-08 12:19:33.598910 | controller | TASK [virtualbmc : Remove vbmc container image] ********************************
2025-10-08 12:19:33.598918 | controller | Wednesday 08 October 2025  12:19:33 +0000 (0:00:00.361)       0:00:43.696 *****
2025-10-08 12:19:33.598928 | controller | ok: [instance]
2025-10-08 12:19:33.599046 | controller |
2025-10-08 12:19:33.599058 | controller | TASK [virtualbmc : Check if VBMC key exists] ***********************************
2025-10-08 12:19:33.599067 | controller | Wednesday 08 October 2025  12:19:33 +0000 (0:00:00.306)       0:00:44.003 *****
2025-10-08 12:19:33.812435 | controller | ok: [instance]
2025-10-08 12:19:33.852556 | controller |
2025-10-08 12:19:33.852587 | controller | TASK [virtualbmc : Slurp key] **************************************************
2025-10-08 12:19:33.852595 | controller | Wednesday 08 October 2025  12:19:33 +0000 (0:00:00.213)       0:00:44.216 *****
2025-10-08 12:19:33.852605 | controller | skipping: [instance]
2025-10-08 12:19:33.892502 | controller |
2025-10-08 12:19:33.892533 | controller | TASK [virtualbmc : Revoke VBMC SSH access] *************************************
2025-10-08 12:19:33.892541 | controller | Wednesday 08 October 2025  12:19:33 +0000 (0:00:00.040)       0:00:44.256 *****
2025-10-08 12:19:33.892551 | controller | skipping: [instance]
2025-10-08 12:19:34.734309 | controller |
2025-10-08 12:19:34.734350 | controller | TASK [virtualbmc : Remove vbmc files] ******************************************
2025-10-08 12:19:34.734359 | controller | Wednesday 08 October 2025  12:19:33 +0000 (0:00:00.040)       0:00:44.296 *****
2025-10-08 12:19:34.734369 | controller | ok: [instance] => (item=/home/zuul/.ssh/vbmc-key)
2025-10-08 12:19:35.588875 | controller | ok: [instance] => (item=/home/zuul/.ssh/vbmc-key.pub)
2025-10-08 12:19:35.588907 | controller | ok: [instance] => (item=/home/zuul/.ssh/virtualbmc.conf)
2025-10-08 12:19:35.588914 | controller | ok: [instance] => (item=/home/zuul/.ssh/vbmcd.sh)
2025-10-08 12:19:35.588921 | controller |
2025-10-08 12:19:35.588926 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-10-08 12:19:35.588932 | controller | Wednesday 08 October 2025  12:19:34 +0000 (0:00:00.840)       0:00:45.137 *****
2025-10-08 12:19:35.588942 | controller | changed: [instance]
2025-10-08 12:19:35.589852 | controller |
2025-10-08 12:19:35.589868 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:19:35.589875 | controller | instance                   : ok=66   changed=21   unreachable=0    failed=0    skipped=29   rescued=0    ignored=0
2025-10-08 12:19:35.589881 | controller |
2025-10-08 12:19:35.589887 | controller | Wednesday 08 October 2025  12:19:35 +0000 (0:00:00.855)       0:00:45.992 *****
2025-10-08 12:19:35.589892 | controller | ===============================================================================
2025-10-08 12:19:35.589900 | controller | virtualbmc : Stop and remove vbmc container ---------------------------- 10.64s
2025-10-08 12:19:35.591062 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 3.57s
2025-10-08 12:19:35.591082 | controller | libvirt_manager : Populate service facts -------------------------------- 2.41s
2025-10-08 12:19:35.591090 | controller | libvirt_manager : Remove workload and volumes --------------------------- 1.44s
2025-10-08 12:19:35.591095 | controller | podman : Ensure podman is installed ------------------------------------- 1.39s
2025-10-08 12:19:35.591101 | controller | dnsmasq : Install needed packages --------------------------------------- 1.34s
2025-10-08 12:19:35.591106 | controller | podman : Ensure podman is installed ------------------------------------- 1.31s
2025-10-08 12:19:35.591112 | controller | virtualbmc : Remove vbmc container image -------------------------------- 1.24s
2025-10-08 12:19:35.591120 | controller | libvirt_manager : Start virtqemud socket service ------------------------ 0.95s
2025-10-08 12:19:35.655460 | controller | Gathering Facts --------------------------------------------------------- 0.87s
2025-10-08 12:19:35.655517 | controller | libvirt_manager : Restart firewalld ------------------------------------- 0.86s
2025-10-08 12:19:35.655526 | controller | virtualbmc : Remove vbmc files ------------------------------------------ 0.84s
2025-10-08 12:19:35.655532 | controller | libvirt_manager : Get installed packages list --------------------------- 0.83s
2025-10-08 12:19:35.655537 | controller | dnsmasq : Stop service -------------------------------------------------- 0.80s
2025-10-08 12:19:35.655543 | controller | virtualbmc : Remove vbmc files ------------------------------------------ 0.78s
2025-10-08 12:19:35.655548 | controller | libvirt_manager : Destroy networks -------------------------------------- 0.66s
2025-10-08 12:19:35.655554 | controller | libvirt_manager : Disable forward in firewalld libvirt zone ------------- 0.59s
2025-10-08 12:19:35.655564 | controller | libvirt_manager : Clean firewalld libvirt zone -------------------------- 0.56s
2025-10-08 12:19:35.655569 | controller | libvirt_manager : Ensure no trace of networks lays in nmcli ------------- 0.46s
2025-10-08 12:19:35.655575 | controller | dnsmasq : Remove main configuration files ------------------------------- 0.41s
2025-10-08 12:19:35.655585 | controller | INFO     Writing /tmp/report.html report.
2025-10-08 12:19:36.053797 | [controller] Waiting on logger
2025-10-08 12:19:41.234352 | [controller] Waiting on logger
2025-10-08 12:19:51.666363 | [controller] Waiting on logger
2025-10-08 12:20:02.098278 | [controller] Waiting on logger
2025-10-08 12:20:05.744337 | [Zuul] Log Stream did not terminate
2025-10-08 12:20:05.744501 | controller | changed
2025-10-08 12:20:05.776276 | 
2025-10-08 12:20:05.776352 | PLAY RECAP
2025-10-08 12:20:05.776394 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 12:20:05.776418 | 
2025-10-08 12:20:05.867326 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 12:20:05.868162 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 12:20:06.432090 | 
2025-10-08 12:20:06.432236 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-10-08 12:20:06.453435 | 
2025-10-08 12:20:06.453552 | TASK [Filter out host if needed]
2025-10-08 12:20:06.462316 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-10-08 12:20:06.466826 | 
2025-10-08 12:20:06.466938 | TASK [Ensure file is present]
2025-10-08 12:20:06.779864 | controller | ok
2025-10-08 12:20:06.786716 | 
2025-10-08 12:20:06.786790 | TASK [Manage molecule report file]
2025-10-08 12:20:06.808389 | [controller] Waiting on logger
2025-10-08 12:20:16.150787 | [controller] Waiting on logger
2025-10-08 12:20:26.546423 | [controller] Waiting on logger
2025-10-08 12:20:36.978317 | [controller] Waiting on logger
2025-10-08 12:20:37.132483 | [Zuul] Log Stream did not terminate
2025-10-08 12:20:37.132665 | controller | changed
2025-10-08 12:20:37.138518 | 
2025-10-08 12:20:37.138582 | TASK [Check if we get ci-framework-data basedir]
2025-10-08 12:20:37.330383 | controller | ok
2025-10-08 12:20:37.340650 | 
2025-10-08 12:20:37.340752 | TASK [Create ci-framework-data log directory for zuul]
2025-10-08 12:20:37.677118 | controller | changed
2025-10-08 12:20:37.682439 | 
2025-10-08 12:20:37.682526 | TASK [Copy ci-framework interesting files]
2025-10-08 12:20:42.742654 | controller | changed
2025-10-08 12:20:42.749573 | 
2025-10-08 12:20:42.749672 | TASK [Get SELinux listing]
2025-10-08 12:20:42.777963 | [controller] Waiting on logger
2025-10-08 12:20:50.418343 | [controller] Waiting on logger
2025-10-08 12:21:04.498337 | [controller] Waiting on logger
2025-10-08 12:21:11.090374 | [controller] Waiting on logger
2025-10-08 12:21:12.985990 | [Zuul] Log Stream did not terminate
2025-10-08 12:21:12.986363 | controller | changed
2025-10-08 12:21:12.992101 | 
2025-10-08 12:21:12.992172 | TASK [Generate log index]
2025-10-08 12:21:13.630703 | controller | changed
2025-10-08 12:21:13.637059 | 
2025-10-08 12:21:13.637160 | TASK [Get some env related data]
2025-10-08 12:21:18.666762 | controller | changed
2025-10-08 12:21:18.672223 | 
2025-10-08 12:21:18.672291 | TASK [Generate list of logs to collect in home directory]
2025-10-08 12:21:19.015651 | controller | ok: All paths examined
2025-10-08 12:21:19.021320 | 
2025-10-08 12:21:19.021411 | LOOP [Copy logs from home directory]
2025-10-08 12:21:19.351465 | controller | changed:
2025-10-08 12:21:19.351577 | controller | {
2025-10-08 12:21:19.351605 | controller |   "atime": 1759925669.786032,
2025-10-08 12:21:19.351625 | controller |   "ctime": 1759925687.4562109,
2025-10-08 12:21:19.351643 | controller |   "dev": 64513,
2025-10-08 12:21:19.351660 | controller |   "gid": 1000,
2025-10-08 12:21:19.351682 | controller |   "gr_name": "zuul",
2025-10-08 12:21:19.351700 | controller |   "inode": 4449368,
2025-10-08 12:21:19.351716 | controller |   "isblk": false,
2025-10-08 12:21:19.351731 | controller |   "ischr": false,
2025-10-08 12:21:19.351745 | controller |   "isdir": false,
2025-10-08 12:21:19.351759 | controller |   "isfifo": false,
2025-10-08 12:21:19.351773 | controller |   "isgid": false,
2025-10-08 12:21:19.351788 | controller |   "islnk": false,
2025-10-08 12:21:19.351802 | controller |   "isreg": true,
2025-10-08 12:21:19.351816 | controller |   "issock": false,
2025-10-08 12:21:19.351830 | controller |   "isuid": false,
2025-10-08 12:21:19.351844 | controller |   "mode": "0644",
2025-10-08 12:21:19.351858 | controller |   "mtime": 1759925687.4562109,
2025-10-08 12:21:19.351872 | controller |   "nlink": 1,
2025-10-08 12:21:19.351886 | controller |   "path": "/home/zuul/ansible.log",
2025-10-08 12:21:19.351903 | controller |   "pw_name": "zuul",
2025-10-08 12:21:19.351949 | controller |   "rgrp": true,
2025-10-08 12:21:19.351968 | controller |   "roth": true,
2025-10-08 12:21:19.351983 | controller |   "rusr": true,
2025-10-08 12:21:19.351998 | controller |   "size": 6749,
2025-10-08 12:21:19.352012 | controller |   "uid": 1000,
2025-10-08 12:21:19.352042 | controller |   "wgrp": false,
2025-10-08 12:21:19.352057 | controller |   "woth": false,
2025-10-08 12:21:19.352071 | controller |   "wusr": true,
2025-10-08 12:21:19.352085 | controller |   "xgrp": false,
2025-10-08 12:21:19.352099 | controller |   "xoth": false,
2025-10-08 12:21:19.352111 | controller |   "xusr": false
2025-10-08 12:21:19.352125 | controller | }
2025-10-08 12:21:19.365624 | 
2025-10-08 12:21:19.365692 | TASK [Copy crio stats log file]
2025-10-08 12:21:19.389211 | controller | skipping: Conditional result was False
2025-10-08 12:21:19.395111 | 
2025-10-08 12:21:19.395181 | TASK [Get SELinux related data]
2025-10-08 12:21:19.419160 | [controller] Waiting on logger
2025-10-08 12:21:29.842363 | [controller] Waiting on logger
2025-10-08 12:21:39.187365 | [controller] Waiting on logger
2025-10-08 12:21:49.618351 | [controller] Waiting on logger
2025-10-08 12:21:49.627205 | [Zuul] Log Stream did not terminate
2025-10-08 12:21:49.627375 | controller | ERROR
2025-10-08 12:21:49.627469 | controller | {
2025-10-08 12:21:49.627498 | controller |   "delta": "0:00:00.008404",
2025-10-08 12:21:49.627519 | controller |   "end": "2025-10-08 12:21:19.600152",
2025-10-08 12:21:49.627539 | controller |   "msg": "non-zero return code",
2025-10-08 12:21:49.627557 | controller |   "rc": 1,
2025-10-08 12:21:49.627574 | controller |   "start": "2025-10-08 12:21:19.591748"
2025-10-08 12:21:49.627592 | controller | }
2025-10-08 12:21:49.627616 | controller | ERROR: Ignoring Errors
2025-10-08 12:21:49.633195 | 
2025-10-08 12:21:49.633262 | TASK [Create system configuration directory]
2025-10-08 12:21:49.855153 | controller | changed
2025-10-08 12:21:49.860509 | 
2025-10-08 12:21:49.860577 | TASK [Get some of the system configurations]
2025-10-08 12:21:53.010457 | [controller] Waiting on logger
2025-10-08 12:22:07.538393 | [controller] Waiting on logger
2025-10-08 12:22:17.970361 | [controller] Waiting on logger
2025-10-08 12:22:20.207393 | [Zuul] Log Stream did not terminate
2025-10-08 12:22:20.207680 | controller | changed
2025-10-08 12:22:20.213743 | 
2025-10-08 12:22:20.213829 | TASK [Copy generated documentation if available]
2025-10-08 12:22:20.229496 | controller | skipping: Conditional result was False
2025-10-08 12:22:20.236808 | 
2025-10-08 12:22:20.236947 | TASK [Copy generated AsciiDoc documentation if available]
2025-10-08 12:22:20.262594 | controller | skipping: Conditional result was False
2025-10-08 12:22:20.269321 | 
2025-10-08 12:22:20.269416 | TASK [Compress logs bigger than 2MB]
2025-10-08 12:22:20.296629 | [controller] Waiting on logger
2025-10-08 12:22:34.546446 | [controller] Waiting on logger
2025-10-08 12:22:35.300783 | controller | changed
2025-10-08 12:22:35.306360 | 
2025-10-08 12:22:35.306438 | TASK [Copy files from workspace on node]
2025-10-08 12:22:35.324652 | controller | ok
2025-10-08 12:22:35.366572 | 
2025-10-08 12:22:35.366678 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 12:22:35.390688 | controller | skipping: Conditional result was False
2025-10-08 12:22:35.397724 | 
2025-10-08 12:22:35.397800 | TASK [fetch-output : Set log path for single node]
2025-10-08 12:22:35.427769 | controller | ok
2025-10-08 12:22:35.432566 | 
2025-10-08 12:22:35.432635 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 12:22:35.640873 | controller -> localhost | ok: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/logs"
2025-10-08 12:22:35.641169 | controller -> localhost | changed: All items complete
2025-10-08 12:22:35.641207 | 
2025-10-08 12:22:35.832684 | controller -> localhost | changed: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/artifacts"
2025-10-08 12:22:36.030709 | controller -> localhost | changed: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/docs"
2025-10-08 12:22:36.048105 | 
2025-10-08 12:22:36.048201 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 12:22:36.657197 | controller | changed:
2025-10-08 12:22:36.657380 | controller | .d..t...... ./
2025-10-08 12:22:36.657410 | controller | >f+++++++++ README.html
2025-10-08 12:22:36.657434 | controller | >f+++++++++ ansible-execution.log
2025-10-08 12:22:36.657455 | controller | >f+++++++++ ansible.log
2025-10-08 12:22:36.657475 | controller | >f+++++++++ dmesg.log
2025-10-08 12:22:36.657494 | controller | >f+++++++++ installed-pkgs.log
2025-10-08 12:22:36.657513 | controller | >f+++++++++ python.log
2025-10-08 12:22:36.657532 | controller | >f+++++++++ registries.conf
2025-10-08 12:22:36.657549 | controller | >f+++++++++ report.html
2025-10-08 12:22:36.657566 | controller | >f+++++++++ selinux-denials.log
2025-10-08 12:22:36.657583 | controller | >f+++++++++ selinux-listing.log
2025-10-08 12:22:36.657600 | controller | cd+++++++++ ci-framework-data/
2025-10-08 12:22:36.657617 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-10-08 12:22:36.657634 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-10-08 12:22:36.657652 | controller | cd+++++++++ ci-framework-data/artifacts/nmstate/
2025-10-08 12:22:36.657669 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-final-state.yaml
2025-10-08 12:22:36.657686 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-state.yaml
2025-10-08 12:22:36.657703 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-10-08 12:22:36.657721 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-10-08 12:22:36.657738 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-10-08 12:22:36.657755 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-10-08 12:22:36.657772 | controller | cd+++++++++ ci-framework-data/logs/
2025-10-08 12:22:36.657788 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-10-08 12:22:36.657804 | controller | cd+++++++++ registries.conf.d/
2025-10-08 12:22:36.657821 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-10-08 12:22:36.657838 | controller | cd+++++++++ system-config/
2025-10-08 12:22:36.657855 | controller | cd+++++++++ system-config/libvirt/
2025-10-08 12:22:36.657871 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-10-08 12:22:36.657888 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-10-08 12:22:36.657904 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-10-08 12:22:36.657965 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-10-08 12:22:36.657987 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-10-08 12:22:36.658027 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-10-08 12:22:36.658047 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-10-08 12:22:36.658065 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-10-08 12:22:36.658088 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-10-08 12:22:36.658106 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-10-08 12:22:36.658124 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-10-08 12:22:36.658142 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-10-08 12:22:36.658159 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-10-08 12:22:36.658176 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-10-08 12:22:36.658193 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-10-08 12:22:36.658210 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-10-08 12:22:37.061426 | controller | changed: .d..t...... ./
2025-10-08 12:22:37.466330 | controller | changed: .d..t...... ./
2025-10-08 12:22:37.481446 | 
2025-10-08 12:22:37.481553 | TASK [Return artifact to Zuul]
2025-10-08 12:22:37.541352 | controller | ok
2025-10-08 12:22:37.562021 | 
2025-10-08 12:22:37.562119 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-10-08 12:22:37.562221 | 
2025-10-08 12:22:37.562250 | PLAY RECAP
2025-10-08 12:22:37.562289 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-10-08 12:22:37.562311 | 
2025-10-08 12:22:37.677001 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 12:22:37.677780 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 12:22:38.266751 | 
2025-10-08 12:22:38.266874 | PLAY [all]
2025-10-08 12:22:38.287287 | 
2025-10-08 12:22:38.287420 | TASK [include_role : fetch-output]
2025-10-08 12:22:38.346694 | controller | ok
2025-10-08 12:22:38.365323 | 
2025-10-08 12:22:38.365444 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 12:22:38.419637 | controller | skipping: Conditional result was False
2025-10-08 12:22:38.425358 | 
2025-10-08 12:22:38.425437 | TASK [fetch-output : Set log path for single node]
2025-10-08 12:22:38.453612 | controller | ok
2025-10-08 12:22:38.461341 | 
2025-10-08 12:22:38.461438 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 12:22:38.884933 | controller -> localhost | ok: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/logs"
2025-10-08 12:22:39.114019 | controller -> localhost | ok: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/artifacts"
2025-10-08 12:22:39.340655 | controller -> localhost | ok: "/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/docs"
2025-10-08 12:22:39.350361 | 
2025-10-08 12:22:39.350464 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 12:22:40.135196 | controller | ok
2025-10-08 12:22:40.135387 | controller | ok: All items complete
2025-10-08 12:22:40.135417 | 
2025-10-08 12:22:40.587224 | controller | ok
2025-10-08 12:22:40.963325 | controller | ok
2025-10-08 12:22:40.975818 | 
2025-10-08 12:22:40.975944 | TASK [include_role : fetch-output-openshift]
2025-10-08 12:22:40.989939 | controller | skipping: Conditional result was False
2025-10-08 12:22:40.996370 | 
2025-10-08 12:22:40.996442 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-08 12:22:41.425201 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.027250
2025-10-08 12:22:41.698536 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007747
2025-10-08 12:22:41.738084 | 
2025-10-08 12:22:41.738205 | PLAY [all]
2025-10-08 12:22:41.753394 | 
2025-10-08 12:22:41.753485 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-08 12:22:42.212950 | controller | changed
2025-10-08 12:22:42.256514 | 
2025-10-08 12:22:42.256605 | PLAY RECAP
2025-10-08 12:22:42.256651 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-08 12:22:42.256676 | 
2025-10-08 12:22:42.421332 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 12:22:42.422113 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-08 12:22:43.075199 | 
2025-10-08 12:22:43.075337 | PLAY [localhost]
2025-10-08 12:22:43.095953 | 
2025-10-08 12:22:43.096051 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-08 12:22:43.598557 | localhost | changed
2025-10-08 12:22:43.603139 | 
2025-10-08 12:22:43.603221 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-08 12:22:43.655753 | localhost | ok
2025-10-08 12:22:43.670686 | 
2025-10-08 12:22:43.670783 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-08 12:22:44.204784 | localhost | changed
2025-10-08 12:22:44.209703 | 
2025-10-08 12:22:44.209775 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-08 12:22:45.437015 | localhost | changed
2025-10-08 12:22:45.442312 | 
2025-10-08 12:22:45.442409 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-08 12:22:45.925664 | localhost | Identity added: /var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/tmp/ansible.xk5_5cuh (/var/lib/zuul/builds/6b49953303b44f15857a37d9a0682a40/work/tmp/ansible.xk5_5cuh)
2025-10-08 12:22:45.925836 | localhost | ok: Runtime: 0:00:00.012663
2025-10-08 12:22:45.930635 | 
2025-10-08 12:22:45.930707 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-08 12:22:46.162742 | localhost | ok: Runtime: 0:00:00.004031
2025-10-08 12:22:46.167732 | 
2025-10-08 12:22:46.171445 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-08 12:22:46.232981 | localhost | changed
2025-10-08 12:22:46.237551 | 
2025-10-08 12:22:46.237632 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-08 12:22:46.648604 | localhost | changed
2025-10-08 12:22:46.674895 | 
2025-10-08 12:22:46.675026 | PLAY [localhost]
2025-10-08 12:22:46.686847 | 
2025-10-08 12:22:46.686945 | TASK [Generate bulk log download script]
2025-10-08 12:22:46.704423 | localhost | ok
2025-10-08 12:22:46.716533 | 
2025-10-08 12:22:46.716628 | TASK [local-log-download : Check API endpoint is defined]
2025-10-08 12:22:46.746386 | localhost | ok: All assertions passed
2025-10-08 12:22:46.751123 | 
2025-10-08 12:22:46.751189 | TASK [local-log-download : Create download script]
2025-10-08 12:22:47.180219 | localhost -> localhost | changed
2025-10-08 12:22:47.243964 | 
2025-10-08 12:22:47.244080 | TASK [Register quick-download link]
2025-10-08 12:22:47.261841 | localhost | ok
2025-10-08 12:22:47.278163 | 
2025-10-08 12:22:47.278228 | PLAY [logserver.rdoproject.org]
2025-10-08 12:22:47.288439 | 
2025-10-08 12:22:47.288503 | TASK [Set zuul-log-path fact]
2025-10-08 12:22:47.305190 | logserver.rdoproject.org | ok
2025-10-08 12:22:47.314700 | 
2025-10-08 12:22:47.314772 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 12:22:47.341066 | logserver.rdoproject.org | ok
2025-10-08 12:22:47.347305 | 
2025-10-08 12:22:47.347463 | TASK [upload-logs : Create log directories]
2025-10-08 12:22:49.135460 | logserver.rdoproject.org | changed
2025-10-08 12:22:49.139449 | 
2025-10-08 12:22:49.139523 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-08 12:22:49.386682 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005959
2025-10-08 12:22:49.391429 | 
2025-10-08 12:22:49.391497 | TASK [upload-logs : Upload logs to log server]
2025-10-08 12:22:51.284156 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-08 12:22:51.289229 | 
2025-10-08 12:22:51.289314 | LOOP [upload-logs : Compress console log and json output]
2025-10-08 12:22:51.329874 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:22:51.340772 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:22:51.346650 | 
2025-10-08 12:22:51.346873 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-08 12:22:51.396491 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:22:51.396740 | 
2025-10-08 12:22:51.401463 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:22:51.408133 | 
2025-10-08 12:22:51.408233 | LOOP [upload-logs : Upload console log and json output]