2025-10-02 14:19:06.801579 | Job console starting...
2025-10-02 14:19:07.036503 | Updating repositories
2025-10-02 14:19:07.762315 | Preparing job workspace
2025-10-02 14:19:16.908052 | Running Ansible setup...
2025-10-02 14:19:21.057310 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 14:19:21.729916 | 
2025-10-02 14:19:21.730013 | PLAY [localhost]
2025-10-02 14:19:21.746358 | 
2025-10-02 14:19:21.746450 | TASK [Gathering Facts]
2025-10-02 14:19:23.394972 | localhost | ok
2025-10-02 14:19:23.416597 | 
2025-10-02 14:19:23.416724 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-02 14:19:24.045298 | localhost -> localhost | changed
2025-10-02 14:19:24.056668 | 
2025-10-02 14:19:24.056761 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-02 14:19:24.992746 | localhost -> localhost | changed
2025-10-02 14:19:25.002314 | 
2025-10-02 14:19:25.002468 | TASK [Setup log path fact]
2025-10-02 14:19:25.046136 | localhost | ok
2025-10-02 14:19:25.067343 | 
2025-10-02 14:19:25.067473 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 14:19:25.111739 | localhost | ok
2025-10-02 14:19:25.127496 | 
2025-10-02 14:19:25.127589 | TASK [emit-job-header : Print job information]
2025-10-02 14:19:25.160943 | # Job Information
2025-10-02 14:19:25.161148 | Ansible Version: 2.15.12
2025-10-02 14:19:25.161181 | Job: cifmw-molecule-sushy_emulator
2025-10-02 14:19:25.161204 | Pipeline: github-check
2025-10-02 14:19:25.161225 | Executor: ibm-bm3-ze.softwarefactory-project.io
2025-10-02 14:19:25.161245 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362
2025-10-02 14:19:25.161265 | Log URL (when completed): https://logserver.rdoproject.org/643/rdoproject.org/6434172efb564516ab8f10a28e69c8ca/
2025-10-02 14:19:25.161289 | Event ID: be9565c0-9f99-11f0-9e8d-1085adf9bc04
2025-10-02 14:19:25.165624 | 
2025-10-02 14:19:25.165694 | LOOP [emit-job-header : Print node information]
2025-10-02 14:19:25.304870 | localhost | ok:
2025-10-02 14:19:25.305010 | localhost | # Node Information
2025-10-02 14:19:25.305041 | localhost | Inventory Hostname: controller
2025-10-02 14:19:25.305068 | localhost | Hostname: np0005466419
2025-10-02 14:19:25.305090 | localhost | Username: zuul
2025-10-02 14:19:25.305112 | localhost | Distro: CentOS 9
2025-10-02 14:19:25.305132 | localhost | Provider: ibm-bm3-nodepool
2025-10-02 14:19:25.305150 | localhost | Region: regionOne
2025-10-02 14:19:25.305168 | localhost | Label: centos-9-stream-crc-2-48-0-xl-ibm
2025-10-02 14:19:25.305187 | localhost | Product Name: OpenStack Compute
2025-10-02 14:19:25.305205 | localhost | Interface IP: 192.168.25.200
2025-10-02 14:19:25.364631 | 
2025-10-02 14:19:25.364932 | PLAY [all]
2025-10-02 14:19:25.377187 | 
2025-10-02 14:19:25.377278 | TASK [Gather network facts]
2025-10-02 14:19:25.873735 | controller | ok
2025-10-02 14:19:25.900253 | 
2025-10-02 14:19:25.900337 | TASK [include_role : start-zuul-console]
2025-10-02 14:19:25.928447 | controller | ok
2025-10-02 14:19:25.940585 | 
2025-10-02 14:19:25.940653 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-02 14:19:26.355511 | controller | ok
2025-10-02 14:19:26.368714 | 
2025-10-02 14:19:26.368811 | TASK [include_role : add-build-sshkey]
2025-10-02 14:19:26.398233 | controller | ok
2025-10-02 14:19:26.414160 | 
2025-10-02 14:19:26.414252 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-02 14:19:26.692804 | controller -> localhost | ok
2025-10-02 14:19:26.699639 | 
2025-10-02 14:19:26.699718 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-02 14:19:26.738645 | controller | ok
2025-10-02 14:19:26.752892 | controller | included: /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-02 14:19:26.760647 | 
2025-10-02 14:19:26.760716 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-02 14:19:27.549219 | controller -> localhost | Generating public/private rsa key pair.
2025-10-02 14:19:27.549431 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/6434172efb564516ab8f10a28e69c8ca_id_rsa.
2025-10-02 14:19:27.549473 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/6434172efb564516ab8f10a28e69c8ca_id_rsa.pub.
2025-10-02 14:19:27.549500 | controller -> localhost | The key fingerprint is:
2025-10-02 14:19:27.549522 | controller -> localhost | SHA256:x4K3sjL6l7io7ui9IkH1W5K+m8xDBcPzVW7dMNAQa9I zuul-build-sshkey
2025-10-02 14:19:27.549542 | controller -> localhost | The key's randomart image is:
2025-10-02 14:19:27.549560 | controller -> localhost | +---[RSA 3072]----+
2025-10-02 14:19:27.549580 | controller -> localhost | |    .     .==o   |
2025-10-02 14:19:27.549601 | controller -> localhost | |   . =   .o o.+  |
2025-10-02 14:19:27.549619 | controller -> localhost | |  . . * .. E . . |
2025-10-02 14:19:27.549648 | controller -> localhost | | .   + = .+      |
2025-10-02 14:19:27.549668 | controller -> localhost | |.   . * S o      |
2025-10-02 14:19:27.549686 | controller -> localhost | |.    + . +       |
2025-10-02 14:19:27.549704 | controller -> localhost | | .  ..o..        |
2025-10-02 14:19:27.549724 | controller -> localhost | |o...*o+o         |
2025-10-02 14:19:27.549742 | controller -> localhost | |B=+=+X+          |
2025-10-02 14:19:27.549760 | controller -> localhost | +----[SHA256]-----+
2025-10-02 14:19:27.549812 | controller -> localhost | ok: Runtime: 0:00:00.189758
2025-10-02 14:19:27.556144 | 
2025-10-02 14:19:27.556206 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-02 14:19:27.574281 | controller | ok
2025-10-02 14:19:27.584479 | controller | included: /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-02 14:19:27.592499 | 
2025-10-02 14:19:27.592565 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-02 14:19:27.643014 | controller | skipping: Conditional result was False
2025-10-02 14:19:27.648577 | 
2025-10-02 14:19:27.648644 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-02 14:19:28.174638 | controller | changed
2025-10-02 14:19:28.179602 | 
2025-10-02 14:19:28.179667 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-02 14:19:28.478603 | controller | ok
2025-10-02 14:19:28.486727 | 
2025-10-02 14:19:28.486851 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-02 14:19:29.768378 | controller | changed
2025-10-02 14:19:29.774792 | 
2025-10-02 14:19:29.774860 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-02 14:19:31.018103 | controller | changed
2025-10-02 14:19:31.023054 | 
2025-10-02 14:19:31.023118 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-02 14:19:31.067433 | controller | skipping: Conditional result was False
2025-10-02 14:19:31.073734 | 
2025-10-02 14:19:31.073814 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-02 14:19:31.605502 | controller -> localhost | changed
2025-10-02 14:19:31.617762 | 
2025-10-02 14:19:31.617858 | TASK [add-build-sshkey : Add back temp key]
2025-10-02 14:19:31.963898 | controller -> localhost | Identity added: /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/6434172efb564516ab8f10a28e69c8ca_id_rsa (zuul-build-sshkey)
2025-10-02 14:19:31.964073 | controller -> localhost | ok: Runtime: 0:00:00.007726
2025-10-02 14:19:31.969626 | 
2025-10-02 14:19:31.969686 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-02 14:19:32.344206 | controller | ok
2025-10-02 14:19:32.348661 | 
2025-10-02 14:19:32.349143 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-02 14:19:32.373079 | controller | skipping: Conditional result was False
2025-10-02 14:19:32.382746 | 
2025-10-02 14:19:32.382860 | TASK [include_role : validate-host]
2025-10-02 14:19:32.403251 | controller | ok
2025-10-02 14:19:32.447702 | 
2025-10-02 14:19:32.447818 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-02 14:19:32.476354 | controller | ok
2025-10-02 14:19:32.481507 | 
2025-10-02 14:19:32.481576 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-02 14:19:32.821229 | controller -> localhost | ok
2025-10-02 14:19:32.826921 | 
2025-10-02 14:19:32.826990 | TASK [validate-host : Collect information about the host]
2025-10-02 14:19:33.548460 | controller | ok
2025-10-02 14:19:33.564238 | 
2025-10-02 14:19:33.564327 | TASK [validate-host : Sanitize hostname]
2025-10-02 14:19:33.651014 | controller | ok
2025-10-02 14:19:33.655660 | 
2025-10-02 14:19:33.655727 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-02 14:19:34.114550 | controller -> localhost | changed
2025-10-02 14:19:34.123012 | 
2025-10-02 14:19:34.123091 | TASK [validate-host : Collect information about zuul worker]
2025-10-02 14:19:34.533022 | controller | ok
2025-10-02 14:19:34.538297 | 
2025-10-02 14:19:34.538377 | TASK [validate-host : Write out all zuul information for each host]
2025-10-02 14:19:34.961333 | controller -> localhost | changed
2025-10-02 14:19:34.974016 | 
2025-10-02 14:19:34.974095 | TASK [include_role : prepare-workspace-openshift]
2025-10-02 14:19:35.016649 | controller | skipping: Conditional result was False
2025-10-02 14:19:35.022092 | 
2025-10-02 14:19:35.022160 | TASK [include_role : remove-zuul-sshkey]
2025-10-02 14:19:35.045669 | controller | skipping: Conditional result was False
2025-10-02 14:19:35.052318 | 
2025-10-02 14:19:35.052413 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 14:19:35.326617 | controller | ok: "logs"
2025-10-02 14:19:35.326843 | controller | ok: All items complete
2025-10-02 14:19:35.326876 | 
2025-10-02 14:19:35.588926 | controller | ok: "artifacts"
2025-10-02 14:19:35.859496 | controller | ok: "docs"
2025-10-02 14:19:35.869231 | 
2025-10-02 14:19:35.869369 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 14:19:36.180619 | controller | changed: "logs"
2025-10-02 14:19:36.447985 | controller | changed: "artifacts"
2025-10-02 14:19:36.690363 | controller | changed: "docs"
2025-10-02 14:19:36.716523 | 
2025-10-02 14:19:36.716627 | PLAY RECAP
2025-10-02 14:19:36.716675 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-02 14:19:36.716703 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 14:19:36.716722 | 
2025-10-02 14:19:36.809500 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 14:19:36.810252 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-02 14:19:37.354260 | 
2025-10-02 14:19:37.354417 | PLAY [all]
2025-10-02 14:19:37.373829 | 
2025-10-02 14:19:37.373902 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-02 14:19:37.432811 | controller | ok
2025-10-02 14:19:37.438148 | 
2025-10-02 14:19:37.438232 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-02 14:19:37.862675 | controller | changed
2025-10-02 14:19:37.868324 | 
2025-10-02 14:19:37.868419 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-02 14:19:39.231253 | controller | changed
2025-10-02 14:19:39.245147 | 
2025-10-02 14:19:39.245244 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-10-02 14:19:39.717415 | controller | changed:
2025-10-02 14:19:39.717592 | controller | {
2025-10-02 14:19:39.717625 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-10-02 14:19:39.717658 | controller | }
2025-10-02 14:19:40.022076 | controller | changed:
2025-10-02 14:19:40.022153 | controller | {
2025-10-02 14:19:40.022182 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-10-02 14:19:40.022204 | controller | }
2025-10-02 14:19:40.328847 | controller | changed:
2025-10-02 14:19:40.328934 | controller | {
2025-10-02 14:19:40.328963 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-10-02 14:19:40.328985 | controller | }
2025-10-02 14:19:40.645347 | controller | changed:
2025-10-02 14:19:40.646410 | controller | {
2025-10-02 14:19:40.646453 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-10-02 14:19:40.646478 | controller | }
2025-10-02 14:19:40.963699 | controller | changed:
2025-10-02 14:19:40.963800 | controller | {
2025-10-02 14:19:40.963836 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-10-02 14:19:40.963864 | controller | }
2025-10-02 14:19:41.271676 | controller | changed:
2025-10-02 14:19:41.271809 | controller | {
2025-10-02 14:19:41.271842 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-10-02 14:19:41.271866 | controller | }
2025-10-02 14:19:41.572917 | controller | changed:
2025-10-02 14:19:41.572994 | controller | {
2025-10-02 14:19:41.573021 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2025-10-02 14:19:41.573043 | controller | }
2025-10-02 14:19:41.871775 | controller | changed:
2025-10-02 14:19:41.871874 | controller | {
2025-10-02 14:19:41.871902 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2025-10-02 14:19:41.871924 | controller | }
2025-10-02 14:19:42.173361 | controller | changed:
2025-10-02 14:19:42.173473 | controller | {
2025-10-02 14:19:42.173501 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-10-02 14:19:42.173522 | controller | }
2025-10-02 14:19:42.464258 | controller | changed:
2025-10-02 14:19:42.464334 | controller | {
2025-10-02 14:19:42.464359 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-10-02 14:19:42.464378 | controller | }
2025-10-02 14:19:42.756081 | controller | changed:
2025-10-02 14:19:42.756162 | controller | {
2025-10-02 14:19:42.756191 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-10-02 14:19:42.756211 | controller | }
2025-10-02 14:19:43.043968 | controller | changed:
2025-10-02 14:19:43.044041 | controller | {
2025-10-02 14:19:43.044079 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-10-02 14:19:43.044100 | controller | }
2025-10-02 14:19:43.335848 | controller | changed:
2025-10-02 14:19:43.335932 | controller | {
2025-10-02 14:19:43.335958 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-10-02 14:19:43.335978 | controller | }
2025-10-02 14:19:43.629953 | controller | changed:
2025-10-02 14:19:43.630077 | controller | {
2025-10-02 14:19:43.630103 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-10-02 14:19:43.630121 | controller | }
2025-10-02 14:19:43.927848 | controller | changed:
2025-10-02 14:19:43.927925 | controller | {
2025-10-02 14:19:43.927952 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-10-02 14:19:43.927972 | controller | }
2025-10-02 14:19:44.277377 | controller | changed:
2025-10-02 14:19:44.277497 | controller | {
2025-10-02 14:19:44.277524 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-10-02 14:19:44.277545 | controller | }
2025-10-02 14:19:44.573504 | controller | changed:
2025-10-02 14:19:44.573594 | controller | {
2025-10-02 14:19:44.573619 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2025-10-02 14:19:44.573639 | controller | }
2025-10-02 14:19:44.870910 | controller | changed:
2025-10-02 14:19:44.871001 | controller | {
2025-10-02 14:19:44.871027 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2025-10-02 14:19:44.871054 | controller | }
2025-10-02 14:19:45.160580 | controller | changed:
2025-10-02 14:19:45.160666 | controller | {
2025-10-02 14:19:45.160692 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-10-02 14:19:45.160712 | controller | }
2025-10-02 14:19:45.457089 | controller | changed:
2025-10-02 14:19:45.457263 | controller | {
2025-10-02 14:19:45.457299 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-10-02 14:19:45.457322 | controller | }
2025-10-02 14:19:45.751771 | controller | changed:
2025-10-02 14:19:45.751887 | controller | {
2025-10-02 14:19:45.751919 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-10-02 14:19:45.751943 | controller | }
2025-10-02 14:19:46.038724 | controller | changed:
2025-10-02 14:19:46.038906 | controller | {
2025-10-02 14:19:46.038942 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-10-02 14:19:46.038964 | controller | }
2025-10-02 14:19:46.335698 | controller | changed:
2025-10-02 14:19:46.335787 | controller | {
2025-10-02 14:19:46.335816 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2025-10-02 14:19:46.335837 | controller | }
2025-10-02 14:19:46.634339 | controller | changed:
2025-10-02 14:19:46.634444 | controller | {
2025-10-02 14:19:46.634470 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-10-02 14:19:46.634489 | controller | }
2025-10-02 14:19:46.931675 | controller | changed:
2025-10-02 14:19:46.931756 | controller | {
2025-10-02 14:19:46.931796 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-10-02 14:19:46.931818 | controller | }
2025-10-02 14:19:47.213801 | controller | changed:
2025-10-02 14:19:47.213897 | controller | {
2025-10-02 14:19:47.213925 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-10-02 14:19:47.213947 | controller | }
2025-10-02 14:19:47.239901 | 
2025-10-02 14:19:47.240009 | TASK [Set timezone to UTC]
2025-10-02 14:19:47.735344 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-10-02 14:19:47.740996 | 
2025-10-02 14:19:47.741061 | TASK [Create nodepool directory]
2025-10-02 14:19:48.013837 | controller | changed
2025-10-02 14:19:48.020772 | 
2025-10-02 14:19:48.020899 | TASK [Create nodepool sub_nodes file]
2025-10-02 14:19:49.029669 | controller | changed
2025-10-02 14:19:49.034889 | 
2025-10-02 14:19:49.034956 | TASK [Create nodepool sub_nodes_private file]
2025-10-02 14:19:50.005526 | controller | changed
2025-10-02 14:19:50.010525 | 
2025-10-02 14:19:50.010587 | LOOP [Populate nodepool sub_nodes file]
2025-10-02 14:19:50.049415 | 
2025-10-02 14:19:50.049544 | LOOP [Populate nodepool sub_nodes_private file]
2025-10-02 14:19:50.078018 | 
2025-10-02 14:19:50.078139 | TASK [Create nodepool primary file]
2025-10-02 14:19:50.101731 | controller | skipping: Conditional result was False
2025-10-02 14:19:50.108029 | 
2025-10-02 14:19:50.108101 | TASK [Create nodepool node_private for this node]
2025-10-02 14:19:51.149355 | controller | changed
2025-10-02 14:19:51.155475 | 
2025-10-02 14:19:51.155545 | LOOP [Copy ssh keys to nodepool directory]
2025-10-02 14:19:51.565961 | controller | ok: Item: id_rsa Runtime: 0:00:00.003995
2025-10-02 14:19:51.566143 | 
2025-10-02 14:19:51.795743 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.004710
2025-10-02 14:19:51.805370 | 
2025-10-02 14:19:51.805509 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-10-02 14:19:52.800872 | controller | changed
2025-10-02 14:19:52.806806 | 
2025-10-02 14:19:52.806874 | TASK [Validate sudoers config after edits]
2025-10-02 14:19:53.086400 | controller | /etc/sudoers: parsed OK
2025-10-02 14:19:53.086465 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-10-02 14:19:53.086473 | controller | /etc/sudoers.d/zuul: parsed OK
2025-10-02 14:19:53.086479 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-10-02 14:19:53.339804 | controller | ok: Runtime: 0:00:00.005203
2025-10-02 14:19:53.345363 | 
2025-10-02 14:19:53.345445 | TASK [Show the environment passed in to job shell scripts]
2025-10-02 14:19:53.624392 | controller | SHELL=/bin/bash
2025-10-02 14:19:53.624439 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-10-02 14:19:53.624449 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-10-02 14:19:53.624454 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/62/3362/41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-02 14:19:53.624460 | controller | PWD=/home/zuul
2025-10-02 14:19:53.624465 | controller | ZUUL_PIPELINE=github-check
2025-10-02 14:19:53.624471 | controller | LOGNAME=zuul
2025-10-02 14:19:53.624476 | controller | XDG_SESSION_TYPE=tty
2025-10-02 14:19:53.624482 | controller | _=/usr/bin/env
2025-10-02 14:19:53.624487 | controller | MOTD_SHOWN=pam
2025-10-02 14:19:53.624492 | controller | HOME=/home/zuul
2025-10-02 14:19:53.624497 | controller | LANG=en_US.UTF-8
2025-10-02 14:19:53.624502 | controller | SSH_CONNECTION=192.168.25.12 55294 192.168.25.200 22
2025-10-02 14:19:53.624507 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2025-10-02 14:19:53.624516 | controller | ZUUL_CHANGE_IDS=3362,41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-02 14:19:53.624521 | controller | WORKSPACE=/home/zuul/workspace
2025-10-02 14:19:53.624534 | controller | XDG_SESSION_CLASS=user
2025-10-02 14:19:53.624579 | controller | SELINUX_ROLE_REQUESTED=
2025-10-02 14:19:53.624587 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-10-02 14:19:53.624593 | controller | USER=zuul
2025-10-02 14:19:53.624598 | controller | ZUUL_VOTING=True
2025-10-02 14:19:53.624603 | controller | BUILD_TIMEOUT=1800000
2025-10-02 14:19:53.624608 | controller | SELINUX_USE_CURRENT_RANGE=
2025-10-02 14:19:53.624613 | controller | SHLVL=1
2025-10-02 14:19:53.624618 | controller | ZUUL_PATCHSET=41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-02 14:19:53.624624 | controller | XDG_SESSION_ID=1
2025-10-02 14:19:53.624629 | controller | ZUUL_BRANCH=main
2025-10-02 14:19:53.624634 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-10-02 14:19:53.624639 | controller | SSH_CLIENT=192.168.25.12 55294 22
2025-10-02 14:19:53.624644 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-10-02 14:19:53.624649 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-10-02 14:19:53.624654 | controller | which_declare=declare -f
2025-10-02 14:19:53.624660 | controller | PATH=/home/zuul/.crc/bin/oc:/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-10-02 14:19:53.624665 | controller | SELINUX_LEVEL_REQUESTED=
2025-10-02 14:19:53.624670 | controller | ZUUL_CHANGE=3362
2025-10-02 14:19:53.624675 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-10-02 14:19:53.624680 | controller | ZUUL_UUID=6434172efb564516ab8f10a28e69c8ca
2025-10-02 14:19:53.624685 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-10-02 14:19:53.624693 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-10-02 14:19:53.624698 | controller | }
2025-10-02 14:19:53.877016 | controller | ok: Runtime: 0:00:00.008744
2025-10-02 14:19:53.883053 | 
2025-10-02 14:19:53.883115 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-10-02 14:19:53.916921 | controller | skipping: Conditional result was False
2025-10-02 14:19:53.922535 | 
2025-10-02 14:19:53.922607 | TASK [Symlink /home/zuul-worker/workspace]
2025-10-02 14:19:54.486027 | controller | skipping: Conditional result was False
2025-10-02 14:19:54.491614 | 
2025-10-02 14:19:54.491693 | TASK [Ensure legacy workspace directory]
2025-10-02 14:19:54.753971 | controller | changed
2025-10-02 14:19:54.781231 | 
2025-10-02 14:19:54.781353 | PLAY RECAP
2025-10-02 14:19:54.781424 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-02 14:19:54.781452 | 
2025-10-02 14:19:54.860143 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-02 14:19:54.860914 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-02 14:19:55.413175 | 
2025-10-02 14:19:55.413308 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-10-02 14:19:55.433627 | 
2025-10-02 14:19:55.433723 | TASK [Create zuul-output directory]
2025-10-02 14:19:55.888073 | controller | changed
2025-10-02 14:19:55.896211 | 
2025-10-02 14:19:55.896290 | TASK [Slurp Zuul inventory test]
2025-10-02 14:19:56.361795 | controller -> localhost | ok
2025-10-02 14:19:56.369684 | 
2025-10-02 14:19:56.370130 | TASK [Save zuul inventory]
2025-10-02 14:19:57.659834 | controller | changed
2025-10-02 14:19:57.665951 | 
2025-10-02 14:19:57.666034 | TASK [Save zuul vars without the change_message]
2025-10-02 14:19:58.679205 | controller | changed
2025-10-02 14:19:58.701475 | 
2025-10-02 14:19:58.701538 | PLAY RECAP
2025-10-02 14:19:58.701582 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 14:19:58.701606 | 
2025-10-02 14:19:58.778049 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-02 14:19:58.778946 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-02 14:19:59.379346 | 
2025-10-02 14:19:59.379467 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-10-02 14:19:59.401287 | 
2025-10-02 14:19:59.401366 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-10-02 14:19:59.433100 | controller | ok
2025-10-02 14:19:59.450501 | 
2025-10-02 14:19:59.450599 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-02 14:19:59.474018 | controller | skipping: Conditional result was False
2025-10-02 14:19:59.479696 | 
2025-10-02 14:19:59.479768 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-02 14:19:59.862361 | controller | ok
2025-10-02 14:19:59.868404 | 
2025-10-02 14:19:59.868484 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-02 14:20:00.769805 | controller | ok
2025-10-02 14:20:00.780631 | 
2025-10-02 14:20:00.780735 | TASK [Prepare workspace]
2025-10-02 14:20:00.800718 | controller | ok
2025-10-02 14:20:00.819522 | 
2025-10-02 14:20:00.819616 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-02 14:20:01.204234 | controller | ok
2025-10-02 14:20:01.219864 | 
2025-10-02 14:20:01.219947 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-02 14:20:03.204146 | controller | Output suppressed because no_log was given
2025-10-02 14:20:03.214868 | 
2025-10-02 14:20:03.214943 | LOOP [Create zuul-output directory]
2025-10-02 14:20:03.459637 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-10-02 14:20:03.676093 | controller | ok: "/home/zuul/zuul-output/logs"
2025-10-02 14:20:03.691005 | 
2025-10-02 14:20:03.691221 | TASK [Install required packages]
2025-10-02 14:20:20.352458 | controller | ok: Nothing to do
2025-10-02 14:20:20.357344 | 
2025-10-02 14:20:20.357429 | TASK [Install venv]
2025-10-02 14:21:18.932444 | controller | changed
2025-10-02 14:21:18.957724 | 
2025-10-02 14:21:18.957824 | PLAY RECAP
2025-10-02 14:21:18.957872 | controller | ok: 7 changed: 3 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-02 14:21:18.957896 | 
2025-10-02 14:21:19.031970 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-02 14:21:19.032735 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-02 14:21:19.572064 | 
2025-10-02 14:21:19.572176 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-10-02 14:21:19.592951 | 
2025-10-02 14:21:19.593034 | TASK [Gather required facts]
2025-10-02 14:21:20.169644 | controller | ok
2025-10-02 14:21:20.175378 | 
2025-10-02 14:21:20.175500 | TASK [Load environment var if instructed to]
2025-10-02 14:21:20.199662 | controller | skipping: Conditional result was False
2025-10-02 14:21:20.205767 | 
2025-10-02 14:21:20.205858 | TASK [Run molecule]
2025-10-02 14:21:21.247259 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-10-02 14:21:21.317441 | controller | INFO     Performing prerun with role_name_check=0...
2025-10-02 14:21:37.653110 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.653565 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.654039 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.654520 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.654990 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+41f2edaa was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0+41f2edaa (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.655467 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.655915 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.656375 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.656822 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.657288 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.657736 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.658187 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.658631 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.659082 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.659530 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/8baae2/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-02 14:21:37.669849 | controller | INFO     Running default > prepare
2025-10-02 14:21:38.336498 | controller |
2025-10-02 14:21:38.336554 | controller | PLAY [Prepare] *****************************************************************
2025-10-02 14:21:38.336631 | controller |
2025-10-02 14:21:38.336731 | controller | TASK [Gathering Facts] *********************************************************
2025-10-02 14:21:38.336872 | controller | Thursday 02 October 2025  14:21:38 +0000 (0:00:00.013)       0:00:00.013 ******
2025-10-02 14:21:39.206043 | controller | ok: [instance]
2025-10-02 14:21:39.206151 | controller |
2025-10-02 14:21:39.206282 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-10-02 14:21:39.206395 | controller | Thursday 02 October 2025  14:21:39 +0000 (0:00:00.871)       0:00:00.884 ******
2025-10-02 14:21:39.223211 | controller | skipping: [instance]
2025-10-02 14:21:39.223332 | controller |
2025-10-02 14:21:39.223424 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-10-02 14:21:39.223559 | controller | Thursday 02 October 2025  14:21:39 +0000 (0:00:00.017)       0:00:00.902 ******
2025-10-02 14:21:39.266178 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-10-02 14:21:39.266258 | controller |
2025-10-02 14:21:39.266379 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-10-02 14:21:39.266520 | controller | Thursday 02 October 2025  14:21:39 +0000 (0:00:00.042)       0:00:00.944 ******
2025-10-02 14:21:39.546443 | controller | ok: [instance]
2025-10-02 14:21:39.546518 | controller |
2025-10-02 14:21:39.546598 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-10-02 14:21:39.546702 | controller | Thursday 02 October 2025  14:21:39 +0000 (0:00:00.280)       0:00:01.224 ******
2025-10-02 14:21:39.873989 | controller | ok: [instance]
2025-10-02 14:21:39.874098 | controller |
2025-10-02 14:21:39.874241 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-10-02 14:21:39.874370 | controller | Thursday 02 October 2025  14:21:39 +0000 (0:00:00.327)       0:00:01.552 ******
2025-10-02 14:21:40.579389 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-10-02 14:21:40.579980 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-10-02 14:21:40.638889 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-10-02 14:21:40.638933 | controller |
2025-10-02 14:21:40.638941 | controller | TASK [Deploy repo-setup] *******************************************************
2025-10-02 14:21:40.638948 | controller | Thursday 02 October 2025  14:21:40 +0000 (0:00:00.705)       0:00:02.257 ******
2025-10-02 14:21:40.638959 | controller |
2025-10-02 14:21:41.214892 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-10-02 14:21:41.214940 | controller | Thursday 02 October 2025  14:21:40 +0000 (0:00:00.059)       0:00:02.317 ******
2025-10-02 14:21:41.214955 | controller | changed: [instance] => (item=tmp)
2025-10-02 14:21:42.046970 | controller | changed: [instance] => (item=artifacts/repositories)
2025-10-02 14:21:42.047060 | controller | changed: [instance] => (item=venv/repo_setup)
2025-10-02 14:21:42.047070 | controller |
2025-10-02 14:21:42.047076 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-10-02 14:21:42.047083 | controller | Thursday 02 October 2025  14:21:41 +0000 (0:00:00.575)       0:00:02.892 ******
2025-10-02 14:21:42.047096 | controller | ok: [instance]
2025-10-02 14:21:43.251626 | controller |
2025-10-02 14:21:43.251675 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-10-02 14:21:43.251689 | controller | Thursday 02 October 2025  14:21:42 +0000 (0:00:00.831)       0:00:03.724 ******
2025-10-02 14:21:43.251701 | controller | changed: [instance]
2025-10-02 14:21:51.292344 | controller |
2025-10-02 14:21:51.292384 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-10-02 14:21:51.292393 | controller | Thursday 02 October 2025  14:21:43 +0000 (0:00:01.205)       0:00:04.929 ******
2025-10-02 14:21:51.292403 | controller | changed: [instance]
2025-10-02 14:21:52.001919 | controller |
2025-10-02 14:21:52.001955 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-10-02 14:21:52.001963 | controller | Thursday 02 October 2025  14:21:51 +0000 (0:00:08.040)       0:00:12.970 ******
2025-10-02 14:21:52.001973 | controller | changed: [instance]
2025-10-02 14:21:52.024521 | controller |
2025-10-02 14:21:52.024548 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-10-02 14:21:52.024555 | controller | Thursday 02 October 2025  14:21:51 +0000 (0:00:00.709)       0:00:13.680 ******
2025-10-02 14:21:52.024565 | controller | skipping: [instance]
2025-10-02 14:21:52.855975 | controller |
2025-10-02 14:21:52.856006 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-10-02 14:21:52.856040 | controller | Thursday 02 October 2025  14:21:52 +0000 (0:00:00.022)       0:00:13.703 ******
2025-10-02 14:21:52.856054 | controller | changed: [instance]
2025-10-02 14:21:52.892159 | controller |
2025-10-02 14:21:52.892200 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-10-02 14:21:52.892211 | controller | Thursday 02 October 2025  14:21:52 +0000 (0:00:00.831)       0:00:14.534 ******
2025-10-02 14:21:52.892223 | controller | skipping: [instance]
2025-10-02 14:21:52.929098 | controller |
2025-10-02 14:21:52.929130 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-10-02 14:21:52.929138 | controller | Thursday 02 October 2025  14:21:52 +0000 (0:00:00.036)       0:00:14.570 ******
2025-10-02 14:21:52.929148 | controller | skipping: [instance]
2025-10-02 14:21:52.929383 | controller |
2025-10-02 14:21:52.929415 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-10-02 14:21:52.966136 | controller | Thursday 02 October 2025  14:21:52 +0000 (0:00:00.036)       0:00:14.607 ******
2025-10-02 14:21:52.966183 | controller | skipping: [instance]
2025-10-02 14:21:52.966219 | controller |
2025-10-02 14:21:52.966230 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-10-02 14:21:52.966255 | controller | Thursday 02 October 2025  14:21:52 +0000 (0:00:00.037)       0:00:14.644 ******
2025-10-02 14:21:53.530200 | controller | changed: [instance]
2025-10-02 14:21:53.991550 | controller |
2025-10-02 14:21:53.991580 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-10-02 14:21:53.991589 | controller | Thursday 02 October 2025  14:21:53 +0000 (0:00:00.563)       0:00:15.208 ******
2025-10-02 14:21:53.991599 | controller | changed: [instance]
2025-10-02 14:21:54.020140 | controller |
2025-10-02 14:21:54.020167 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-10-02 14:21:54.020176 | controller | Thursday 02 October 2025  14:21:53 +0000 (0:00:00.461)       0:00:15.669 ******
2025-10-02 14:21:54.020185 | controller | skipping: [instance]
2025-10-02 14:21:54.020265 | controller |
2025-10-02 14:21:54.020288 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-10-02 14:21:54.020300 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.028)       0:00:15.698 ******
2025-10-02 14:21:54.049790 | controller | skipping: [instance]
2025-10-02 14:21:54.077088 | controller |
2025-10-02 14:21:54.077115 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-10-02 14:21:54.077123 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.029)       0:00:15.728 ******
2025-10-02 14:21:54.077133 | controller | skipping: [instance]
2025-10-02 14:21:54.077215 | controller |
2025-10-02 14:21:54.077235 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-10-02 14:21:54.077247 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.027)       0:00:15.755 ******
2025-10-02 14:21:54.113525 | controller | ok: [instance]
2025-10-02 14:21:54.139115 | controller |
2025-10-02 14:21:54.139140 | controller | TASK [repo_setup : Create download directory] **********************************
2025-10-02 14:21:54.139148 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.036)       0:00:15.791 ******
2025-10-02 14:21:54.139157 | controller | skipping: [instance]
2025-10-02 14:21:54.165302 | controller |
2025-10-02 14:21:54.165330 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-10-02 14:21:54.165338 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.025)       0:00:15.817 ******
2025-10-02 14:21:54.165358 | controller | skipping: [instance]
2025-10-02 14:21:54.165453 | controller |
2025-10-02 14:21:54.165593 | controller | TASK [Download the RPM] ********************************************************
2025-10-02 14:21:54.165734 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.026)       0:00:15.844 ******
2025-10-02 14:21:54.191056 | controller | skipping: [instance]
2025-10-02 14:21:54.191195 | controller |
2025-10-02 14:21:54.191337 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-10-02 14:21:54.191461 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.025)       0:00:15.870 ******
2025-10-02 14:21:54.216899 | controller | skipping: [instance]
2025-10-02 14:21:54.217034 | controller |
2025-10-02 14:21:54.217185 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-10-02 14:21:54.217315 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.025)       0:00:15.895 ******
2025-10-02 14:21:54.242207 | controller | skipping: [instance]
2025-10-02 14:21:54.242231 | controller |
2025-10-02 14:21:54.242242 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-10-02 14:21:54.242387 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.025)       0:00:15.920 ******
2025-10-02 14:21:54.269888 | controller | skipping: [instance]
2025-10-02 14:21:54.270034 | controller |
2025-10-02 14:21:54.270201 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-10-02 14:21:54.270353 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.027)       0:00:15.948 ******
2025-10-02 14:21:54.297806 | controller | skipping: [instance]
2025-10-02 14:21:54.297906 | controller |
2025-10-02 14:21:54.298031 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-10-02 14:21:54.298163 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.027)       0:00:15.976 ******
2025-10-02 14:21:54.477803 | controller | ok: [instance]
2025-10-02 14:21:54.688700 | controller |
2025-10-02 14:21:54.688730 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-10-02 14:21:54.688739 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.179)       0:00:16.156 ******
2025-10-02 14:21:54.688749 | controller | changed: [instance]
2025-10-02 14:21:54.921093 | controller |
2025-10-02 14:21:54.921126 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-10-02 14:21:54.921134 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.210)       0:00:16.367 ******
2025-10-02 14:21:54.921145 | controller | changed: [instance]
2025-10-02 14:21:54.942624 | controller |
2025-10-02 14:21:54.942657 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-10-02 14:21:54.942684 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.232)       0:00:16.599 ******
2025-10-02 14:21:54.942695 | controller | skipping: [instance]
2025-10-02 14:21:54.965707 | controller |
2025-10-02 14:21:54.965740 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-10-02 14:21:54.965748 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.021)       0:00:16.620 ******
2025-10-02 14:21:54.965758 | controller | skipping: [instance]
2025-10-02 14:21:54.988460 | controller |
2025-10-02 14:21:54.988491 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-10-02 14:21:54.988499 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.023)       0:00:16.644 ******
2025-10-02 14:21:54.988509 | controller | skipping: [instance]
2025-10-02 14:21:55.010833 | controller |
2025-10-02 14:21:55.010856 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-10-02 14:21:55.010872 | controller | Thursday 02 October 2025  14:21:54 +0000 (0:00:00.022)       0:00:16.666 ******
2025-10-02 14:21:55.010886 | controller | skipping: [instance]
2025-10-02 14:21:55.032959 | controller |
2025-10-02 14:21:55.032983 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-10-02 14:21:55.032992 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.022)       0:00:16.689 ******
2025-10-02 14:21:55.033002 | controller | skipping: [instance]
2025-10-02 14:21:55.056097 | controller |
2025-10-02 14:21:55.056120 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-10-02 14:21:55.056137 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.022)       0:00:16.711 ******
2025-10-02 14:21:55.056149 | controller | skipping: [instance]
2025-10-02 14:21:55.056318 | controller |
2025-10-02 14:21:55.056464 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-10-02 14:21:55.056599 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.023)       0:00:16.734 ******
2025-10-02 14:21:55.073119 | controller | skipping: [instance]
2025-10-02 14:21:55.073299 | controller |
2025-10-02 14:21:55.073451 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-10-02 14:21:55.073586 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.017)       0:00:16.751 ******
2025-10-02 14:21:55.102454 | controller | skipping: [instance]
2025-10-02 14:21:55.102619 | controller |
2025-10-02 14:21:55.102783 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-10-02 14:21:55.102931 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.029)       0:00:16.781 ******
2025-10-02 14:21:55.117988 | controller | skipping: [instance]
2025-10-02 14:21:55.118167 | controller |
2025-10-02 14:21:55.118326 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-10-02 14:21:55.118476 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.015)       0:00:16.796 ******
2025-10-02 14:21:55.137806 | controller | skipping: [instance]
2025-10-02 14:21:55.137949 | controller |
2025-10-02 14:21:55.138116 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-10-02 14:21:55.138261 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.019)       0:00:16.816 ******
2025-10-02 14:21:55.166713 | controller | skipping: [instance]
2025-10-02 14:21:55.166924 | controller |
2025-10-02 14:21:55.167136 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-10-02 14:21:55.167317 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.028)       0:00:16.845 ******
2025-10-02 14:21:55.198110 | controller | skipping: [instance]
2025-10-02 14:21:55.198325 | controller |
2025-10-02 14:21:55.198506 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-10-02 14:21:55.198684 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.031)       0:00:16.876 ******
2025-10-02 14:21:55.227844 | controller | skipping: [instance]
2025-10-02 14:21:55.228010 | controller |
2025-10-02 14:21:55.228205 | controller | TASK [test_deps : Install additional packages] *********************************
2025-10-02 14:21:55.228349 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.029)       0:00:16.906 ******
2025-10-02 14:21:55.256810 | controller | skipping: [instance]
2025-10-02 14:21:55.257002 | controller |
2025-10-02 14:21:55.257211 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-10-02 14:21:55.257385 | controller | Thursday 02 October 2025  14:21:55 +0000 (0:00:00.028)       0:00:16.935 ******
2025-10-02 14:22:54.127976 | controller | ok: [instance]
2025-10-02 14:22:54.128217 | controller |
2025-10-02 14:22:54.128367 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-10-02 14:22:54.128503 | controller | Thursday 02 October 2025  14:22:54 +0000 (0:00:58.870)       0:01:15.806 ******
2025-10-02 14:22:55.364572 | controller | ok: [instance]
2025-10-02 14:22:55.364792 | controller |
2025-10-02 14:22:55.364968 | controller | TASK [test_deps : Install extra packages] **************************************
2025-10-02 14:22:55.365171 | controller | Thursday 02 October 2025  14:22:55 +0000 (0:00:01.236)       0:01:17.043 ******
2025-10-02 14:22:55.397306 | controller | skipping: [instance]
2025-10-02 14:22:55.397478 | controller |
2025-10-02 14:22:55.397617 | controller | TASK [Ensure CRC is started] ***************************************************
2025-10-02 14:22:55.397790 | controller | Thursday 02 October 2025  14:22:55 +0000 (0:00:00.032)       0:01:17.075 ******
2025-10-02 14:25:37.093677 | controller | changed: [instance]
2025-10-02 14:25:37.422451 | controller |
2025-10-02 14:25:37.422559 | controller | TASK [Inject crc hostname/IP in hosts] *****************************************
2025-10-02 14:25:37.422572 | controller | Thursday 02 October 2025  14:25:37 +0000 (0:02:41.695)       0:03:58.770 ******
2025-10-02 14:25:37.422594 | controller | changed: [instance]
2025-10-02 14:25:37.481647 | controller |
2025-10-02 14:25:37.481705 | controller | PLAY RECAP *********************************************************************
2025-10-02 14:25:37.481714 | controller | instance                   : ok=21   changed=11   unreachable=0    failed=0    skipped=30   rescued=0    ignored=0
2025-10-02 14:25:37.481720 | controller |
2025-10-02 14:25:37.481750 | controller | Thursday 02 October 2025  14:25:37 +0000 (0:00:00.324)       0:03:59.095 ******
2025-10-02 14:25:37.481759 | controller | ===============================================================================
2025-10-02 14:25:37.481764 | controller | Ensure CRC is started ------------------------------------------------- 161.70s
2025-10-02 14:25:37.481769 | controller | test_deps : Install selinux python libs -------------------------------- 58.87s
2025-10-02 14:25:37.481775 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.04s
2025-10-02 14:25:37.481780 | controller | test_deps : Install python yaml libs ------------------------------------ 1.24s
2025-10-02 14:25:37.481785 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.21s
2025-10-02 14:25:37.481790 | controller | Gathering Facts --------------------------------------------------------- 0.87s
2025-10-02 14:25:37.481796 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.83s
2025-10-02 14:25:37.481810 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.83s
2025-10-02 14:25:37.481816 | controller | repo_setup : Install repo-setup package --------------------------------- 0.71s
2025-10-02 14:25:37.481821 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.71s
2025-10-02 14:25:37.481826 | controller | repo_setup : Ensure directories are present ----------------------------- 0.58s
2025-10-02 14:25:37.481831 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.56s
2025-10-02 14:25:37.481837 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.46s
2025-10-02 14:25:37.481842 | controller | test_deps : Disable ubi host subscription-manager integration ----------- 0.33s
2025-10-02 14:25:37.481847 | controller | Inject crc hostname/IP in hosts ----------------------------------------- 0.32s
2025-10-02 14:25:37.481852 | controller | test_deps : Detect mirrors file ----------------------------------------- 0.28s
2025-10-02 14:25:37.481857 | controller | repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist) --- 0.23s
2025-10-02 14:25:37.481863 | controller | repo_setup : Use RDO proxy mirrors -------------------------------------- 0.21s
2025-10-02 14:25:37.481868 | controller | repo_setup : Check for /etc/ci/mirror_info.sh --------------------------- 0.18s
2025-10-02 14:25:37.481873 | controller | Deploy repo-setup ------------------------------------------------------- 0.06s
2025-10-02 14:25:37.481888 | controller | INFO     Running default > converge
2025-10-02 14:25:37.958535 | controller |
2025-10-02 14:25:37.958677 | controller | PLAY [Converge] ****************************************************************
2025-10-02 14:25:37.958796 | controller |
2025-10-02 14:25:37.958927 | controller | TASK [Gathering Facts] *********************************************************
2025-10-02 14:25:37.959112 | controller | Thursday 02 October 2025  14:25:37 +0000 (0:00:00.016)       0:00:00.016 ******
2025-10-02 14:25:38.821786 | controller | ok: [instance]
2025-10-02 14:25:38.841948 | controller |
2025-10-02 14:25:38.841982 | controller | TASK [Load networking_definition] **********************************************
2025-10-02 14:25:38.841990 | controller | Thursday 02 October 2025  14:25:38 +0000 (0:00:00.863)       0:00:00.879 ******
2025-10-02 14:25:38.842000 | controller | ok: [instance]
2025-10-02 14:25:38.842045 | controller |
2025-10-02 14:25:38.842057 | controller | TASK [Check if new ssh keypair exists] *****************************************
2025-10-02 14:25:38.842204 | controller | Thursday 02 October 2025  14:25:38 +0000 (0:00:00.020)       0:00:00.899 ******
2025-10-02 14:25:38.867184 | controller |
2025-10-02 14:25:39.158951 | controller | TASK [recognize_ssh_keypair : Check if id_ed25519 key exists] ******************
2025-10-02 14:25:39.158981 | controller | Thursday 02 October 2025  14:25:38 +0000 (0:00:00.025)       0:00:00.924 ******
2025-10-02 14:25:39.158993 | controller | ok: [instance]
2025-10-02 14:25:39.159187 | controller |
2025-10-02 14:25:39.159241 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair exists] ******************
2025-10-02 14:25:39.159261 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.291)       0:00:01.216 ******
2025-10-02 14:25:39.179718 | controller | ok: [instance]
2025-10-02 14:25:39.179768 | controller |
2025-10-02 14:25:39.180025 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair does not exists] *********
2025-10-02 14:25:39.202121 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.021)       0:00:01.237 ******
2025-10-02 14:25:39.202154 | controller | skipping: [instance]
2025-10-02 14:25:39.202307 | controller |
2025-10-02 14:25:39.202347 | controller | TASK [Add the crc host dynamically] ********************************************
2025-10-02 14:25:39.223566 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.022)       0:00:01.260 ******
2025-10-02 14:25:39.223594 | controller | changed: [instance]
2025-10-02 14:25:39.223614 | controller |
2025-10-02 14:25:39.223620 | controller | TASK [Add ansible_host entry to "controller-0"] ********************************
2025-10-02 14:25:39.223627 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.021)       0:00:01.281 ******
2025-10-02 14:25:39.249456 | controller | changed: [instance]
2025-10-02 14:25:39.581091 | controller |
2025-10-02 14:25:39.581121 | controller | TASK [Add host key to controller-0] ********************************************
2025-10-02 14:25:39.581129 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.025)       0:00:01.307 ******
2025-10-02 14:25:39.581140 | controller | changed: [instance]
2025-10-02 14:25:39.581165 | controller |
2025-10-02 14:25:39.581173 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-10-02 14:25:39.581302 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.331)       0:00:01.638 ******
2025-10-02 14:25:39.894640 | controller | ok: [instance]
2025-10-02 14:25:39.894719 | controller |
2025-10-02 14:25:39.894748 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-10-02 14:25:39.894760 | controller | Thursday 02 October 2025  14:25:39 +0000 (0:00:00.313)       0:00:01.952 ******
2025-10-02 14:25:40.080794 | controller | changed: [instance]
2025-10-02 14:25:40.264685 | controller |
2025-10-02 14:25:40.264715 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-10-02 14:25:40.264724 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.186)       0:00:02.138 ******
2025-10-02 14:25:40.264733 | controller | ok: [instance]
2025-10-02 14:25:40.292509 | controller |
2025-10-02 14:25:40.292535 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-10-02 14:25:40.292543 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.183)       0:00:02.322 ******
2025-10-02 14:25:40.292553 | controller | skipping: [instance]
2025-10-02 14:25:40.309503 | controller |
2025-10-02 14:25:40.309527 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-10-02 14:25:40.309534 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.027)       0:00:02.350 ******
2025-10-02 14:25:40.309544 | controller | skipping: [instance]
2025-10-02 14:25:40.329736 | controller |
2025-10-02 14:25:40.329762 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-10-02 14:25:40.329770 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.017)       0:00:02.367 ******
2025-10-02 14:25:40.329780 | controller | ok: [instance]
2025-10-02 14:25:40.329978 | controller |
2025-10-02 14:25:40.329996 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-10-02 14:25:40.357963 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.020)       0:00:02.387 ******
2025-10-02 14:25:40.357990 | controller | skipping: [instance]
2025-10-02 14:25:40.358084 | controller |
2025-10-02 14:25:40.358102 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-10-02 14:25:40.358112 | controller | Thursday 02 October 2025  14:25:40 +0000 (0:00:00.028)       0:00:02.415 ******
2025-10-02 14:25:54.446490 | controller | changed: [instance]
2025-10-02 14:25:54.446550 | controller |
2025-10-02 14:25:54.446561 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-10-02 14:25:54.446659 | controller | Thursday 02 October 2025  14:25:54 +0000 (0:00:14.088)       0:00:16.504 ******
2025-10-02 14:25:54.688611 | controller | changed: [instance]
2025-10-02 14:25:54.688684 | controller |
2025-10-02 14:25:54.688798 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-10-02 14:25:54.688930 | controller | Thursday 02 October 2025  14:25:54 +0000 (0:00:00.242)       0:00:16.746 ******
2025-10-02 14:25:55.193244 | controller | changed: [instance]
2025-10-02 14:25:55.193323 | controller |
2025-10-02 14:25:55.193433 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-10-02 14:25:55.193539 | controller | Thursday 02 October 2025  14:25:55 +0000 (0:00:00.504)       0:00:17.251 ******
2025-10-02 14:25:55.795519 | controller | changed: [instance]
2025-10-02 14:25:55.795569 | controller |
2025-10-02 14:25:55.795685 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-10-02 14:25:55.795800 | controller | Thursday 02 October 2025  14:25:55 +0000 (0:00:00.602)       0:00:17.853 ******
2025-10-02 14:25:55.995902 | controller | ok: [instance]
2025-10-02 14:25:55.995962 | controller |
2025-10-02 14:25:55.996117 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-10-02 14:25:55.996227 | controller | Thursday 02 October 2025  14:25:55 +0000 (0:00:00.200)       0:00:18.053 ******
2025-10-02 14:25:56.679234 | controller | ok: [instance]
2025-10-02 14:25:56.679320 | controller |
2025-10-02 14:25:56.679435 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-10-02 14:25:56.679594 | controller | Thursday 02 October 2025  14:25:56 +0000 (0:00:00.683)       0:00:18.737 ******
2025-10-02 14:25:57.644978 | controller | changed: [instance]
2025-10-02 14:25:57.727728 | controller |
2025-10-02 14:25:57.727765 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-10-02 14:25:57.727774 | controller | Thursday 02 October 2025  14:25:57 +0000 (0:00:00.964)       0:00:19.702 ******
2025-10-02 14:25:57.727787 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-10-02 14:25:57.727955 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-10-02 14:25:57.727971 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-10-02 14:25:57.728113 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-10-02 14:25:57.728124 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-10-02 14:25:57.728132 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-10-02 14:25:57.728318 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-10-02 14:25:57.728368 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-10-02 14:25:57.728665 | controller |
2025-10-02 14:25:58.088202 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-10-02 14:25:58.088240 | controller | Thursday 02 October 2025  14:25:57 +0000 (0:00:00.083)       0:00:19.785 ******
2025-10-02 14:25:58.088254 | controller | ok: [instance]
2025-10-02 14:25:58.088576 | controller |
2025-10-02 14:25:58.088592 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-10-02 14:25:58.428099 | controller | Thursday 02 October 2025  14:25:58 +0000 (0:00:00.359)       0:00:20.145 ******
2025-10-02 14:25:58.428141 | controller | ok: [instance]
2025-10-02 14:25:58.428524 | controller |
2025-10-02 14:25:58.794870 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-10-02 14:25:58.794907 | controller | Thursday 02 October 2025  14:25:58 +0000 (0:00:00.339)       0:00:20.485 ******
2025-10-02 14:25:58.794919 | controller | ok: [instance]
2025-10-02 14:25:59.172885 | controller |
2025-10-02 14:25:59.172917 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-10-02 14:25:59.172939 | controller | Thursday 02 October 2025  14:25:58 +0000 (0:00:00.364)       0:00:20.849 ******
2025-10-02 14:25:59.172949 | controller | ok: [instance]
2025-10-02 14:25:59.543231 | controller |
2025-10-02 14:25:59.543269 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-10-02 14:25:59.543278 | controller | Thursday 02 October 2025  14:25:59 +0000 (0:00:00.378)       0:00:21.228 ******
2025-10-02 14:25:59.543287 | controller | ok: [instance]
2025-10-02 14:25:59.881175 | controller |
2025-10-02 14:25:59.881207 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-10-02 14:25:59.881216 | controller | Thursday 02 October 2025  14:25:59 +0000 (0:00:00.369)       0:00:21.597 ******
2025-10-02 14:25:59.881226 | controller | ok: [instance]
2025-10-02 14:26:00.215739 | controller |
2025-10-02 14:26:00.215769 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-10-02 14:26:00.215777 | controller | Thursday 02 October 2025  14:25:59 +0000 (0:00:00.340)       0:00:21.938 ******
2025-10-02 14:26:00.215786 | controller | ok: [instance]
2025-10-02 14:26:00.540356 | controller |
2025-10-02 14:26:00.540406 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-10-02 14:26:00.540415 | controller | Thursday 02 October 2025  14:26:00 +0000 (0:00:00.334)       0:00:22.273 ******
2025-10-02 14:26:00.540426 | controller | ok: [instance]
2025-10-02 14:26:00.540444 | controller |
2025-10-02 14:26:00.540597 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-10-02 14:26:00.540636 | controller | Thursday 02 October 2025  14:26:00 +0000 (0:00:00.324)       0:00:22.598 ******
2025-10-02 14:26:00.879620 | controller | ok: [instance]
2025-10-02 14:26:00.879682 | controller |
2025-10-02 14:26:00.879792 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-10-02 14:26:00.879909 | controller | Thursday 02 October 2025  14:26:00 +0000 (0:00:00.336)       0:00:22.934 ******
2025-10-02 14:26:01.237761 | controller | ok: [instance]
2025-10-02 14:26:01.237825 | controller |
2025-10-02 14:26:01.238053 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-10-02 14:26:01.238229 | controller | Thursday 02 October 2025  14:26:01 +0000 (0:00:00.361)       0:00:23.295 ******
2025-10-02 14:26:01.603185 | controller | ok: [instance]
2025-10-02 14:26:01.961749 | controller |
2025-10-02 14:26:01.961902 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-10-02 14:26:01.961952 | controller | Thursday 02 October 2025  14:26:01 +0000 (0:00:00.364)       0:00:23.660 ******
2025-10-02 14:26:01.961984 | controller | ok: [instance]
2025-10-02 14:26:02.349568 | controller |
2025-10-02 14:26:02.349681 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-10-02 14:26:02.349693 | controller | Thursday 02 October 2025  14:26:01 +0000 (0:00:00.355)       0:00:24.016 ******
2025-10-02 14:26:02.349721 | controller | ok: [instance]
2025-10-02 14:26:02.763296 | controller |
2025-10-02 14:26:02.763374 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-10-02 14:26:02.763384 | controller | Thursday 02 October 2025  14:26:02 +0000 (0:00:00.386)       0:00:24.403 ******
2025-10-02 14:26:02.763409 | controller | ok: [instance]
2025-10-02 14:26:03.195105 | controller |
2025-10-02 14:26:03.195157 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-10-02 14:26:03.195166 | controller | Thursday 02 October 2025  14:26:02 +0000 (0:00:00.417)       0:00:24.820 ******
2025-10-02 14:26:03.195180 | controller | ok: [instance]
2025-10-02 14:26:03.195274 | controller |
2025-10-02 14:26:03.195286 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-10-02 14:26:03.649271 | controller | Thursday 02 October 2025  14:26:03 +0000 (0:00:00.429)       0:00:25.249 ******
2025-10-02 14:26:03.649358 | controller | ok: [instance]
2025-10-02 14:26:04.027258 | controller |
2025-10-02 14:26:04.027308 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-10-02 14:26:04.027317 | controller | Thursday 02 October 2025  14:26:03 +0000 (0:00:00.452)       0:00:25.702 ******
2025-10-02 14:26:04.027332 | controller | ok: [instance]
2025-10-02 14:26:04.428051 | controller |
2025-10-02 14:26:04.428168 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-10-02 14:26:04.428223 | controller | Thursday 02 October 2025  14:26:04 +0000 (0:00:00.380)       0:00:26.082 ******
2025-10-02 14:26:04.428250 | controller | ok: [instance]
2025-10-02 14:26:04.781872 | controller |
2025-10-02 14:26:04.781906 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-10-02 14:26:04.781914 | controller | Thursday 02 October 2025  14:26:04 +0000 (0:00:00.399)       0:00:26.481 ******
2025-10-02 14:26:04.781924 | controller | ok: [instance]
2025-10-02 14:26:05.169126 | controller |
2025-10-02 14:26:05.169182 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-10-02 14:26:05.169191 | controller | Thursday 02 October 2025  14:26:04 +0000 (0:00:00.357)       0:00:26.839 ******
2025-10-02 14:26:05.169202 | controller | ok: [instance]
2025-10-02 14:26:05.169400 | controller |
2025-10-02 14:26:05.522707 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-10-02 14:26:05.522744 | controller | Thursday 02 October 2025  14:26:05 +0000 (0:00:00.387)       0:00:27.226 ******
2025-10-02 14:26:05.522756 | controller | ok: [instance]
2025-10-02 14:26:05.861638 | controller |
2025-10-02 14:26:05.861677 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-10-02 14:26:05.861686 | controller | Thursday 02 October 2025  14:26:05 +0000 (0:00:00.353)       0:00:27.580 ******
2025-10-02 14:26:05.861698 | controller | ok: [instance]
2025-10-02 14:26:05.861724 | controller |
2025-10-02 14:26:05.861734 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-10-02 14:26:06.194237 | controller | Thursday 02 October 2025  14:26:05 +0000 (0:00:00.338)       0:00:27.919 ******
2025-10-02 14:26:06.194283 | controller | ok: [instance]
2025-10-02 14:26:06.195034 | controller |
2025-10-02 14:26:06.195061 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-10-02 14:26:06.522580 | controller | Thursday 02 October 2025  14:26:06 +0000 (0:00:00.332)       0:00:28.251 ******
2025-10-02 14:26:06.522622 | controller | ok: [instance]
2025-10-02 14:26:06.522705 | controller |
2025-10-02 14:26:06.522719 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-10-02 14:26:06.522736 | controller | Thursday 02 October 2025  14:26:06 +0000 (0:00:00.328)       0:00:28.580 ******
2025-10-02 14:26:06.543347 | controller | skipping: [instance]
2025-10-02 14:26:06.543443 | controller |
2025-10-02 14:26:06.543459 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-10-02 14:26:06.543519 | controller | Thursday 02 October 2025  14:26:06 +0000 (0:00:00.020)       0:00:28.601 ******
2025-10-02 14:26:06.808140 | controller | ok: [instance]
2025-10-02 14:26:06.808173 | controller |
2025-10-02 14:26:06.808181 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-10-02 14:26:06.808189 | controller | Thursday 02 October 2025  14:26:06 +0000 (0:00:00.264)       0:00:28.865 ******
2025-10-02 14:26:07.206361 | controller | ok: [instance]
2025-10-02 14:26:07.588134 | controller |
2025-10-02 14:26:07.588166 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-10-02 14:26:07.588174 | controller | Thursday 02 October 2025  14:26:07 +0000 (0:00:00.398)       0:00:29.263 ******
2025-10-02 14:26:07.588185 | controller | changed: [instance]
2025-10-02 14:26:07.588213 | controller |
2025-10-02 14:26:07.588221 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-10-02 14:26:07.588348 | controller | Thursday 02 October 2025  14:26:07 +0000 (0:00:00.381)       0:00:29.645 ******
2025-10-02 14:26:07.946345 | controller | [WARNING]: Reset is not implemented for this connection
2025-10-02 14:26:07.956084 | controller | changed: [instance]
2025-10-02 14:26:07.956643 | controller |
2025-10-02 14:26:08.032669 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-10-02 14:26:08.032706 | controller | Thursday 02 October 2025  14:26:07 +0000 (0:00:00.352)       0:00:29.998 ******
2025-10-02 14:26:08.032714 | controller |
2025-10-02 14:26:08.032720 | controller | TASK [Create virtual baremetal VMs] ********************************************
2025-10-02 14:26:08.032726 | controller | Thursday 02 October 2025  14:26:07 +0000 (0:00:00.015)       0:00:30.014 ******
2025-10-02 14:26:08.032736 | controller |
2025-10-02 14:26:08.072341 | controller | TASK [libvirt_manager : Import layout generator if needed] *********************
2025-10-02 14:26:08.072380 | controller | Thursday 02 October 2025  14:26:08 +0000 (0:00:00.075)       0:00:30.090 ******
2025-10-02 14:26:08.072394 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_layout.yml for instance
2025-10-02 14:26:08.072481 | controller |
2025-10-02 14:26:08.072675 | controller | TASK [libvirt_manager : Chose right parameter for layout definition] ***********
2025-10-02 14:26:08.114222 | controller | Thursday 02 October 2025  14:26:08 +0000 (0:00:00.040)       0:00:30.130 ******
2025-10-02 14:26:08.114249 | controller | ok: [instance]
2025-10-02 14:26:08.114391 | controller |
2025-10-02 14:26:08.114406 | controller | TASK [libvirt_manager : Patch the layout if needed] ****************************
2025-10-02 14:26:08.114442 | controller | Thursday 02 October 2025  14:26:08 +0000 (0:00:00.041)       0:00:30.172 ******
2025-10-02 14:26:08.176137 | controller | skipping: [instance]
2025-10-02 14:26:08.176162 | controller |
2025-10-02 14:26:08.176172 | controller | TASK [libvirt_manager : Enable forwarding in the libvirt zone] *****************
2025-10-02 14:26:08.176240 | controller | Thursday 02 October 2025  14:26:08 +0000 (0:00:00.061)       0:00:30.234 ******
2025-10-02 14:26:08.625896 | controller | changed: [instance]
2025-10-02 14:26:09.171514 | controller |
2025-10-02 14:26:09.171566 | controller | TASK [libvirt_manager : Enable masquerading for public traffic] ****************
2025-10-02 14:26:09.171575 | controller | Thursday 02 October 2025  14:26:08 +0000 (0:00:00.449)       0:00:30.683 ******
2025-10-02 14:26:09.171591 | controller | changed: [instance]
2025-10-02 14:26:10.008982 | controller |
2025-10-02 14:26:10.009048 | controller | TASK [libvirt_manager : Ensure firewalld is restarts] **************************
2025-10-02 14:26:10.009060 | controller | Thursday 02 October 2025  14:26:09 +0000 (0:00:00.536)       0:00:31.219 ******
2025-10-02 14:26:10.009066 | controller |
2025-10-02 14:26:10.009072 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-10-02 14:26:10.009079 | controller | Thursday 02 October 2025  14:26:09 +0000 (0:00:00.009)       0:00:31.228 ******
2025-10-02 14:26:10.009092 | controller | changed: [instance]
2025-10-02 14:26:10.038773 | controller |
2025-10-02 14:26:10.038799 | controller | TASK [Deploy virtualbmc] *******************************************************
2025-10-02 14:26:10.038807 | controller | Thursday 02 October 2025  14:26:10 +0000 (0:00:00.837)       0:00:32.066 ******
2025-10-02 14:26:10.038828 | controller | skipping: [instance]
2025-10-02 14:26:10.068888 | controller |
2025-10-02 14:26:10.068912 | controller | TASK [libvirt_manager : Let the project know we have vbmc available] ***********
2025-10-02 14:26:10.068920 | controller | Thursday 02 October 2025  14:26:10 +0000 (0:00:00.029)       0:00:32.096 ******
2025-10-02 14:26:10.068930 | controller | skipping: [instance]
2025-10-02 14:26:10.690455 | controller |
2025-10-02 14:26:10.690493 | controller | TASK [libvirt_manager : Create needed workload directory] **********************
2025-10-02 14:26:10.690504 | controller | Thursday 02 October 2025  14:26:10 +0000 (0:00:00.029)       0:00:32.126 ******
2025-10-02 14:26:10.690519 | controller | changed: [instance] => (item=workload)
2025-10-02 14:26:11.142795 | controller | changed: [instance] => (item=reproducer-inventory)
2025-10-02 14:26:11.142870 | controller | changed: [instance] => (item=volumes)
2025-10-02 14:26:11.142879 | controller |
2025-10-02 14:26:11.142885 | controller | TASK [libvirt_manager : Allow QEMU on workload directory] **********************
2025-10-02 14:26:11.142891 | controller | Thursday 02 October 2025  14:26:10 +0000 (0:00:00.621)       0:00:32.747 ******
2025-10-02 14:26:11.142906 | controller | changed: [instance] => (item=workload)
2025-10-02 14:26:11.142911 | controller | changed: [instance] => (item=volumes)
2025-10-02 14:26:11.142918 | controller |
2025-10-02 14:26:11.143168 | controller | TASK [libvirt_manager : Generate networking data] ******************************
2025-10-02 14:26:11.220465 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.452)       0:00:33.200 ******
2025-10-02 14:26:11.220537 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/generate_networking_data.yml for instance
2025-10-02 14:26:11.239463 | controller |
2025-10-02 14:26:11.239507 | controller | TASK [libvirt_manager : Ensure fact is existing, and empty] ********************
2025-10-02 14:26:11.239526 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.077)       0:00:33.277 ******
2025-10-02 14:26:11.239540 | controller | ok: [instance]
2025-10-02 14:26:11.438157 | controller |
2025-10-02 14:26:11.438221 | controller | TASK [libvirt_manager : Check if we get an existing interfaces-info.yml] *******
2025-10-02 14:26:11.438230 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.019)       0:00:33.297 ******
2025-10-02 14:26:11.438246 | controller | ok: [instance]
2025-10-02 14:26:11.466913 | controller |
2025-10-02 14:26:11.466960 | controller | TASK [libvirt_manager : Load file if exists] ***********************************
2025-10-02 14:26:11.466968 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.198)       0:00:33.495 ******
2025-10-02 14:26:11.466983 | controller | skipping: [instance]
2025-10-02 14:26:11.495242 | controller |
2025-10-02 14:26:11.495281 | controller | TASK [libvirt_manager : Update fact with existing content] *********************
2025-10-02 14:26:11.495290 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.029)       0:00:33.524 ******
2025-10-02 14:26:11.495302 | controller | skipping: [instance]
2025-10-02 14:26:11.495508 | controller |
2025-10-02 14:26:11.548632 | controller | TASK [libvirt_manager : Generate VM list] **************************************
2025-10-02 14:26:11.548668 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.028)       0:00:33.553 ******
2025-10-02 14:26:11.548683 | controller | ok: [instance]
2025-10-02 14:26:11.645035 | controller |
2025-10-02 14:26:11.645075 | controller | TASK [libvirt_manager : Generate/update mapping all nodes] *********************
2025-10-02 14:26:11.645083 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.052)       0:00:33.606 ******
2025-10-02 14:26:11.645099 | controller | ok: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-02 14:26:11.680704 | controller | ok: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-10-02 14:26:11.680742 | controller |
2025-10-02 14:26:11.680751 | controller | TASK [libvirt_manager : Append baremetal nodes if needed] **********************
2025-10-02 14:26:11.680757 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.096)       0:00:33.702 ******
2025-10-02 14:26:11.680769 | controller | skipping: [instance]
2025-10-02 14:26:11.681086 | controller |
2025-10-02 14:26:12.042658 | controller | TASK [libvirt_manager : Dump MAC mapping] **************************************
2025-10-02 14:26:12.042722 | controller | Thursday 02 October 2025  14:26:11 +0000 (0:00:00.036)       0:00:33.738 ******
2025-10-02 14:26:12.042741 | controller | changed: [instance]
2025-10-02 14:26:12.135155 | controller |
2025-10-02 14:26:12.135222 | controller | TASK [libvirt_manager : Inject all VMs in the inventory] ***********************
2025-10-02 14:26:12.135231 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.361)       0:00:34.100 ******
2025-10-02 14:26:12.135247 | controller | changed: [instance] => (item=Adding compute-0 to computes)
2025-10-02 14:26:12.135291 | controller | changed: [instance] => (item=Adding compute-1 to computes)
2025-10-02 14:26:12.135297 | controller |
2025-10-02 14:26:12.135304 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-10-02 14:26:12.135372 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.092)       0:00:34.192 ******
2025-10-02 14:26:12.158614 | controller | skipping: [instance]
2025-10-02 14:26:12.158857 | controller |
2025-10-02 14:26:12.180691 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-10-02 14:26:12.180733 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.023)       0:00:34.216 ******
2025-10-02 14:26:12.180747 | controller | skipping: [instance]
2025-10-02 14:26:12.180863 | controller |
2025-10-02 14:26:12.180888 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-10-02 14:26:12.204542 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.022)       0:00:34.238 ******
2025-10-02 14:26:12.204582 | controller | skipping: [instance]
2025-10-02 14:26:12.204645 | controller |
2025-10-02 14:26:12.204655 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-10-02 14:26:12.204664 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.023)       0:00:34.262 ******
2025-10-02 14:26:12.227089 | controller | skipping: [instance]
2025-10-02 14:26:12.227393 | controller |
2025-10-02 14:26:12.244448 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-10-02 14:26:12.244485 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.022)       0:00:34.285 ******
2025-10-02 14:26:12.244498 | controller | ok: [instance]
2025-10-02 14:26:12.244552 | controller |
2025-10-02 14:26:12.244565 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-10-02 14:26:12.244617 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.017)       0:00:34.302 ******
2025-10-02 14:26:12.311576 | controller | ok: [instance] => (item={'networks': {'ctlplane': {'network': '192.168.122.0/24', 'gateway': '192.168.122.1', 'dns': ['192.168.122.253', '192.168.122.254'], 'search-domain': 'ctlplane.example.local', 'mtu': 1500}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}}}}})
2025-10-02 14:26:12.311635 | controller |
2025-10-02 14:26:12.311643 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-10-02 14:26:12.311653 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.066)       0:00:34.369 ******
2025-10-02 14:26:12.328689 | controller | skipping: [instance]
2025-10-02 14:26:12.328896 | controller |
2025-10-02 14:26:12.328929 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-10-02 14:26:12.328940 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.017)       0:00:34.386 ******
2025-10-02 14:26:12.536109 | controller | changed: [instance]
2025-10-02 14:26:12.939349 | controller |
2025-10-02 14:26:12.939397 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-10-02 14:26:12.939407 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.206)       0:00:34.593 ******
2025-10-02 14:26:12.939421 | controller | changed: [instance]
2025-10-02 14:26:12.939465 | controller |
2025-10-02 14:26:12.939475 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-10-02 14:26:12.989641 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.402)       0:00:34.996 ******
2025-10-02 14:26:12.989689 | controller | ok: [instance]
2025-10-02 14:26:12.989711 | controller |
2025-10-02 14:26:12.989867 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-10-02 14:26:12.989880 | controller | Thursday 02 October 2025  14:26:12 +0000 (0:00:00.050)       0:00:35.047 ******
2025-10-02 14:26:13.010699 | controller | ok: [instance]
2025-10-02 14:26:13.010907 | controller |
2025-10-02 14:26:13.010920 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-10-02 14:26:13.413174 | controller | Thursday 02 October 2025  14:26:13 +0000 (0:00:00.021)       0:00:35.068 ******
2025-10-02 14:26:13.413226 | controller | changed: [instance]
2025-10-02 14:26:13.413329 | controller |
2025-10-02 14:26:13.413345 | controller | TASK [libvirt_manager : Manage networks if needed] *****************************
2025-10-02 14:26:13.413431 | controller | Thursday 02 October 2025  14:26:13 +0000 (0:00:00.398)       0:00:35.466 ******
2025-10-02 14:26:13.481620 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks.yml for instance
2025-10-02 14:26:13.481662 | controller |
2025-10-02 14:26:13.481767 | controller | TASK [libvirt_manager : Define the localized variables for performing the tasks here.] ***
2025-10-02 14:26:13.481923 | controller | Thursday 02 October 2025  14:26:13 +0000 (0:00:00.072)       0:00:35.539 ******
2025-10-02 14:26:13.523459 | controller | ok: [instance] => (item=public)
2025-10-02 14:26:13.523544 | controller |
2025-10-02 14:26:13.523682 | controller | TASK [libvirt_manager : Ensure networks are defined] ***************************
2025-10-02 14:26:13.523809 | controller | Thursday 02 October 2025  14:26:13 +0000 (0:00:00.041)       0:00:35.581 ******
2025-10-02 14:26:13.872663 | controller | changed: [instance] => (item=cifmw-public)
2025-10-02 14:26:13.872734 | controller |
2025-10-02 14:26:13.873216 | controller | TASK [libvirt_manager : Ensure networks are created/started] *******************
2025-10-02 14:26:13.873341 | controller | Thursday 02 October 2025  14:26:13 +0000 (0:00:00.348)       0:00:35.929 ******
2025-10-02 14:26:14.185177 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:14.185267 | controller |
2025-10-02 14:26:14.185392 | controller | TASK [libvirt_manager : Ensure networks are active] ****************************
2025-10-02 14:26:14.185485 | controller | Thursday 02 October 2025  14:26:14 +0000 (0:00:00.313)       0:00:36.243 ******
2025-10-02 14:26:14.423106 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:14.423143 | controller |
2025-10-02 14:26:14.423278 | controller | TASK [libvirt_manager : Ensure networks enabled to autostart] ******************
2025-10-02 14:26:14.423381 | controller | Thursday 02 October 2025  14:26:14 +0000 (0:00:00.237)       0:00:36.481 ******
2025-10-02 14:26:14.651171 | controller | changed: [instance] => (item=cifmw-public)
2025-10-02 14:26:14.651243 | controller |
2025-10-02 14:26:14.651352 | controller | TASK [libvirt_manager : Add a dummy interface to bridges if required] **********
2025-10-02 14:26:14.651465 | controller | Thursday 02 October 2025  14:26:14 +0000 (0:00:00.228)       0:00:36.709 ******
2025-10-02 14:26:14.705338 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_networks_dummy_interfaces.yml for instance
2025-10-02 14:26:14.705447 | controller |
2025-10-02 14:26:14.705569 | controller | TASK [libvirt_manager : Fetch present bridge interfaces] ***********************
2025-10-02 14:26:14.705689 | controller | Thursday 02 October 2025  14:26:14 +0000 (0:00:00.054)       0:00:36.763 ******
2025-10-02 14:26:14.899432 | controller | ok: [instance]
2025-10-02 14:26:14.899526 | controller |
2025-10-02 14:26:14.899607 | controller | TASK [libvirt_manager : Fetch bridges ports link info] *************************
2025-10-02 14:26:14.899721 | controller | Thursday 02 October 2025  14:26:14 +0000 (0:00:00.194)       0:00:36.957 ******
2025-10-02 14:26:15.111601 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:15.111648 | controller |
2025-10-02 14:26:15.111751 | controller | TASK [Create dummy interfaces to ensure bridges are UP] ************************
2025-10-02 14:26:15.111874 | controller | Thursday 02 October 2025  14:26:15 +0000 (0:00:00.212)       0:00:37.169 ******
2025-10-02 14:26:15.181300 | controller |
2025-10-02 14:26:15.181396 | controller | TASK [ci_nmstate : Ensure we have needed facts] ********************************
2025-10-02 14:26:15.181519 | controller | Thursday 02 October 2025  14:26:15 +0000 (0:00:00.069)       0:00:37.239 ******
2025-10-02 14:26:15.217487 | controller | skipping: [instance]
2025-10-02 14:26:15.217598 | controller |
2025-10-02 14:26:15.217719 | controller | TASK [ci_nmstate : Install required packages on instance] **********************
2025-10-02 14:26:15.217845 | controller | Thursday 02 October 2025  14:26:15 +0000 (0:00:00.036)       0:00:37.275 ******
2025-10-02 14:26:19.855168 | controller | changed: [instance]
2025-10-02 14:26:20.065949 | controller |
2025-10-02 14:26:20.065990 | controller | TASK [ci_nmstate : Create the target NMstate dump directory] *******************
2025-10-02 14:26:20.065998 | controller | Thursday 02 October 2025  14:26:19 +0000 (0:00:04.636)       0:00:41.911 ******
2025-10-02 14:26:20.066026 | controller | changed: [instance]
2025-10-02 14:26:20.066040 | controller |
2025-10-02 14:26:20.066573 | controller | TASK [ci_nmstate : Save nmstate state for instance] ****************************
2025-10-02 14:26:20.450162 | controller | Thursday 02 October 2025  14:26:20 +0000 (0:00:00.212)       0:00:42.123 ******
2025-10-02 14:26:20.450208 | controller | changed: [instance]
2025-10-02 14:26:20.450523 | controller |
2025-10-02 14:26:20.450621 | controller | TASK [ci_nmstate : Apply the desidered state on instance] **********************
2025-10-02 14:26:20.450636 | controller | Thursday 02 October 2025  14:26:20 +0000 (0:00:00.384)       0:00:42.508 ******
2025-10-02 14:26:22.401504 | controller | changed: [instance]
2025-10-02 14:26:22.401568 | controller |
2025-10-02 14:26:22.401676 | controller | TASK [ci_nmstate : Save nmstate debugging data for instance] *******************
2025-10-02 14:26:22.401785 | controller | Thursday 02 October 2025  14:26:22 +0000 (0:00:01.951)       0:00:44.459 ******
2025-10-02 14:26:22.779381 | controller | changed: [instance]
2025-10-02 14:26:22.779442 | controller |
2025-10-02 14:26:22.779570 | controller | TASK [Create extra network configuration] **************************************
2025-10-02 14:26:22.779676 | controller | Thursday 02 October 2025  14:26:22 +0000 (0:00:00.377)       0:00:44.837 ******
2025-10-02 14:26:22.812142 | controller | skipping: [instance]
2025-10-02 14:26:22.843751 | controller |
2025-10-02 14:26:22.843798 | controller | TASK [libvirt_manager : Ensure extra networks is in correct zone] **************
2025-10-02 14:26:22.843807 | controller | Thursday 02 October 2025  14:26:22 +0000 (0:00:00.032)       0:00:44.869 ******
2025-10-02 14:26:22.843848 | controller | skipping: [instance]
2025-10-02 14:26:22.843957 | controller |
2025-10-02 14:26:22.843968 | controller | TASK [libvirt_manager : Refresh networking facts on host] **********************
2025-10-02 14:26:22.844735 | controller | Thursday 02 October 2025  14:26:22 +0000 (0:00:00.032)       0:00:44.901 ******
2025-10-02 14:26:23.319221 | controller | ok: [instance]
2025-10-02 14:26:23.319313 | controller |
2025-10-02 14:26:23.319532 | controller | TASK [libvirt_manager : Build needed network/dnsmasq related content] **********
2025-10-02 14:26:23.319700 | controller | Thursday 02 October 2025  14:26:23 +0000 (0:00:00.475)       0:00:45.377 ******
2025-10-02 14:26:23.466306 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:23.466353 | controller |
2025-10-02 14:26:23.466472 | controller | TASK [dnsmasq : Install needed packages] ***************************************
2025-10-02 14:26:23.466581 | controller | Thursday 02 October 2025  14:26:23 +0000 (0:00:00.146)       0:00:45.524 ******
2025-10-02 14:26:24.709633 | controller | ok: [instance]
2025-10-02 14:26:24.709709 | controller |
2025-10-02 14:26:24.710002 | controller | TASK [dnsmasq : Ensure SELinux knows about the new files and directories] ******
2025-10-02 14:26:28.539702 | controller | Thursday 02 October 2025  14:26:24 +0000 (0:00:01.243)       0:00:46.767 ******
2025-10-02 14:26:28.539748 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.conf', 'setype': 'dnsmasq_etc_t'})
2025-10-02 14:26:28.539774 | controller | changed: [instance] => (item={'target': '/etc/cifmw-dnsmasq.d(/.*)?', 'setype': 'dnsmasq_etc_t'})
2025-10-02 14:26:28.539782 | controller | changed: [instance] => (item={'target': '/var/run/cifmw-dnsmasq.pid', 'setype': 'dnsmasq_var_run_t'})
2025-10-02 14:26:28.539803 | controller |
2025-10-02 14:26:28.540113 | controller | TASK [dnsmasq : Manage configuration directory] ********************************
2025-10-02 14:26:28.764505 | controller | Thursday 02 October 2025  14:26:28 +0000 (0:00:03.829)       0:00:50.597 ******
2025-10-02 14:26:28.764561 | controller | changed: [instance]
2025-10-02 14:26:29.135527 | controller |
2025-10-02 14:26:29.135559 | controller | TASK [dnsmasq : Manage systemd unit file] **************************************
2025-10-02 14:26:29.135568 | controller | Thursday 02 October 2025  14:26:28 +0000 (0:00:00.224)       0:00:50.822 ******
2025-10-02 14:26:29.135579 | controller | changed: [instance]
2025-10-02 14:26:29.135604 | controller |
2025-10-02 14:26:29.135612 | controller | TASK [dnsmasq : Manage base configuration file] ********************************
2025-10-02 14:26:29.135730 | controller | Thursday 02 October 2025  14:26:29 +0000 (0:00:00.371)       0:00:51.193 ******
2025-10-02 14:26:29.537675 | controller | changed: [instance]
2025-10-02 14:26:29.566948 | controller |
2025-10-02 14:26:29.566982 | controller | TASK [dnsmasq : Render listener configuration] *********************************
2025-10-02 14:26:29.566990 | controller | Thursday 02 October 2025  14:26:29 +0000 (0:00:00.401)       0:00:51.595 ******
2025-10-02 14:26:29.567000 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/listener.yml for instance
2025-10-02 14:26:29.989124 | controller |
2025-10-02 14:26:29.989163 | controller | TASK [dnsmasq : Create listener configuration file] ****************************
2025-10-02 14:26:29.989172 | controller | Thursday 02 October 2025  14:26:29 +0000 (0:00:00.029)       0:00:51.624 ******
2025-10-02 14:26:29.989183 | controller | changed: [instance]
2025-10-02 14:26:29.989388 | controller |
2025-10-02 14:26:30.010734 | controller | TASK [dnsmasq : Remove listener configuration file] ****************************
2025-10-02 14:26:30.010763 | controller | Thursday 02 October 2025  14:26:29 +0000 (0:00:00.422)       0:00:52.046 ******
2025-10-02 14:26:30.010777 | controller | skipping: [instance]
2025-10-02 14:26:30.047230 | controller |
2025-10-02 14:26:30.047261 | controller | TASK [dnsmasq : Render dns configuration] **************************************
2025-10-02 14:26:30.047270 | controller | Thursday 02 October 2025  14:26:30 +0000 (0:00:00.021)       0:00:52.068 ******
2025-10-02 14:26:30.047280 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/dns.yml for instance
2025-10-02 14:26:30.457208 | controller |
2025-10-02 14:26:30.457250 | controller | TASK [dnsmasq : Create dns configuration file] *********************************
2025-10-02 14:26:30.457258 | controller | Thursday 02 October 2025  14:26:30 +0000 (0:00:00.036)       0:00:52.104 ******
2025-10-02 14:26:30.457283 | controller | changed: [instance]
2025-10-02 14:26:30.457304 | controller |
2025-10-02 14:26:30.457372 | controller | TASK [dnsmasq : Remove dns configuration file] *********************************
2025-10-02 14:26:30.457476 | controller | Thursday 02 October 2025  14:26:30 +0000 (0:00:00.410)       0:00:52.515 ******
2025-10-02 14:26:30.476316 | controller | skipping: [instance]
2025-10-02 14:26:30.476517 | controller |
2025-10-02 14:26:30.476684 | controller | TASK [dnsmasq : Add localhost addresses from defined dnsmasq listen addresses to loopback interface] ***
2025-10-02 14:26:30.476716 | controller | Thursday 02 October 2025  14:26:30 +0000 (0:00:00.019)       0:00:52.534 ******
2025-10-02 14:26:30.694615 | controller | ok: [instance] => (item=127.0.0.2)
2025-10-02 14:26:30.694672 | controller |
2025-10-02 14:26:30.694948 | controller | TASK [dnsmasq : Enable and start service] **************************************
2025-10-02 14:26:31.420846 | controller | Thursday 02 October 2025  14:26:30 +0000 (0:00:00.217)       0:00:52.752 ******
2025-10-02 14:26:31.420885 | controller | changed: [instance]
2025-10-02 14:26:31.438856 | controller |
2025-10-02 14:26:31.438886 | controller | TASK [dnsmasq : Stop service] **************************************************
2025-10-02 14:26:31.438896 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.725)       0:00:53.478 ******
2025-10-02 14:26:31.438908 | controller | skipping: [instance]
2025-10-02 14:26:31.438937 | controller |
2025-10-02 14:26:31.438947 | controller | TASK [dnsmasq : Remove unit file] **********************************************
2025-10-02 14:26:31.439129 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.018)       0:00:53.496 ******
2025-10-02 14:26:31.457131 | controller | skipping: [instance]
2025-10-02 14:26:31.484832 | controller |
2025-10-02 14:26:31.484864 | controller | TASK [dnsmasq : Remove main configuration files] *******************************
2025-10-02 14:26:31.484873 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.018)       0:00:53.515 ******
2025-10-02 14:26:31.484883 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.conf)
2025-10-02 14:26:31.484959 | controller | skipping: [instance] => (item=/etc/cifmw-dnsmasq.d)
2025-10-02 14:26:31.484973 | controller | skipping: [instance]
2025-10-02 14:26:31.485088 | controller |
2025-10-02 14:26:31.485187 | controller | TASK [Create dnsmasq networks] *************************************************
2025-10-02 14:26:31.485288 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.027)       0:00:53.542 ******
2025-10-02 14:26:31.559110 | controller |
2025-10-02 14:26:31.559200 | controller | TASK [dnsmasq : Assert mandatory parameter] ************************************
2025-10-02 14:26:31.559321 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.073)       0:00:53.616 ******
2025-10-02 14:26:31.588447 | controller | ok: [instance] => changed=false
2025-10-02 14:26:31.588531 | controller |   msg: All assertions passed
2025-10-02 14:26:31.588627 | controller |
2025-10-02 14:26:31.588728 | controller | TASK [dnsmasq : Assert mandatory parameters for new network] *******************
2025-10-02 14:26:31.588832 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.029)       0:00:53.646 ******
2025-10-02 14:26:31.626097 | controller | ok: [instance] => changed=false
2025-10-02 14:26:31.626202 | controller |   msg: All assertions passed
2025-10-02 14:26:31.626301 | controller |
2025-10-02 14:26:31.626402 | controller | TASK [dnsmasq : Create network] ************************************************
2025-10-02 14:26:31.626501 | controller | Thursday 02 October 2025  14:26:31 +0000 (0:00:00.037)       0:00:53.684 ******
2025-10-02 14:26:32.080863 | controller | changed: [instance]
2025-10-02 14:26:32.080918 | controller |
2025-10-02 14:26:32.081049 | controller | TASK [dnsmasq : Remove network] ************************************************
2025-10-02 14:26:32.081175 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.454)       0:00:54.138 ******
2025-10-02 14:26:32.099489 | controller | skipping: [instance]
2025-10-02 14:26:32.099578 | controller |
2025-10-02 14:26:32.099685 | controller | TASK [dnsmasq : Remove dhcp host files] ****************************************
2025-10-02 14:26:32.099781 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.018)       0:00:54.157 ******
2025-10-02 14:26:32.124432 | controller | skipping: [instance]
2025-10-02 14:26:32.124478 | controller |
2025-10-02 14:26:32.124578 | controller | TASK [libvirt_manager : Ensure network is in correct zone] *********************
2025-10-02 14:26:32.124698 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.024)       0:00:54.182 ******
2025-10-02 14:26:32.441493 | controller | changed: [instance] => (item=cifmw-public)
2025-10-02 14:26:32.441535 | controller |
2025-10-02 14:26:32.441667 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-10-02 14:26:32.441701 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.316)       0:00:54.499 ******
2025-10-02 14:26:32.470400 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/network_bridge_info_gen.yml for instance => (item=cifmw-public)
2025-10-02 14:26:32.470551 | controller |
2025-10-02 14:26:32.470677 | controller | TASK [libvirt_manager : Extract IP address from network bridges] ***************
2025-10-02 14:26:32.470807 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.028)       0:00:54.528 ******
2025-10-02 14:26:32.802141 | controller | ok: [instance]
2025-10-02 14:26:32.802207 | controller |
2025-10-02 14:26:32.802340 | controller | TASK [libvirt_manager : Set network_bridge_info fact with network and address] ***
2025-10-02 14:26:32.802477 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.331)       0:00:54.860 ******
2025-10-02 14:26:32.835775 | controller | ok: [instance]
2025-10-02 14:26:32.835851 | controller |
2025-10-02 14:26:32.835976 | controller | TASK [libvirt_manager : Output _network_data] **********************************
2025-10-02 14:26:32.836099 | controller | Thursday 02 October 2025  14:26:32 +0000 (0:00:00.033)       0:00:54.893 ******
2025-10-02 14:26:33.199513 | controller | changed: [instance]
2025-10-02 14:26:33.199568 | controller |
2025-10-02 14:26:33.199747 | controller | TASK [libvirt_manager : Output pub_net] ****************************************
2025-10-02 14:26:33.545658 | controller | Thursday 02 October 2025  14:26:33 +0000 (0:00:00.363)       0:00:55.257 ******
2025-10-02 14:26:33.545692 | controller | changed: [instance]
2025-10-02 14:26:33.545739 | controller |
2025-10-02 14:26:33.545867 | controller | TASK [libvirt_manager : Output _cifmw_libvirt_manager_layout] ******************
2025-10-02 14:26:33.545973 | controller | Thursday 02 October 2025  14:26:33 +0000 (0:00:00.346)       0:00:55.603 ******
2025-10-02 14:26:33.893977 | controller | changed: [instance]
2025-10-02 14:26:33.894062 | controller |
2025-10-02 14:26:33.894186 | controller | TASK [libvirt_manager : Expose patch for networking_mapper] ********************
2025-10-02 14:26:33.894285 | controller | Thursday 02 October 2025  14:26:33 +0000 (0:00:00.348)       0:00:55.952 ******
2025-10-02 14:26:34.014405 | controller | ok: [instance]
2025-10-02 14:26:34.014472 | controller |
2025-10-02 14:26:34.014585 | controller | TASK [libvirt_manager : Save networking_mapper patch] **************************
2025-10-02 14:26:34.014685 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.120)       0:00:56.072 ******
2025-10-02 14:26:34.362771 | controller | changed: [instance]
2025-10-02 14:26:34.363082 | controller |
2025-10-02 14:26:34.363111 | controller | TASK [networking_mapper : Check for Networking Definition file existence] ******
2025-10-02 14:26:34.363121 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.348)       0:00:56.420 ******
2025-10-02 14:26:34.386453 | controller | skipping: [instance]
2025-10-02 14:26:34.386544 | controller |
2025-10-02 14:26:34.386651 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************
2025-10-02 14:26:34.386753 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.023)       0:00:56.444 ******
2025-10-02 14:26:34.410560 | controller | skipping: [instance]
2025-10-02 14:26:34.410647 | controller |
2025-10-02 14:26:34.410751 | controller | TASK [networking_mapper : Check for interfaces info file existence] ************
2025-10-02 14:26:34.410866 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.024)       0:00:56.468 ******
2025-10-02 14:26:34.434577 | controller | skipping: [instance]
2025-10-02 14:26:34.434692 | controller |
2025-10-02 14:26:34.434840 | controller | TASK [networking_mapper : Load the interfaces info from file] ******************
2025-10-02 14:26:34.434979 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.023)       0:00:56.492 ******
2025-10-02 14:26:34.458259 | controller | skipping: [instance]
2025-10-02 14:26:34.458433 | controller |
2025-10-02 14:26:34.458448 | controller | TASK [networking_mapper : Ensure local fact is empty] **************************
2025-10-02 14:26:34.458545 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.023)       0:00:56.516 ******
2025-10-02 14:26:34.476887 | controller | ok: [instance]
2025-10-02 14:26:34.573693 | controller |
2025-10-02 14:26:34.573733 | controller | TASK [networking_mapper : Set the input Networking Definition and patch it if needed] ***
2025-10-02 14:26:34.573743 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.018)       0:00:56.534 ******
2025-10-02 14:26:34.573756 | controller | ok: [instance] => (item={'networks': {'ctlplane': {'network': '192.168.122.0/24', 'gateway': '192.168.122.1', 'dns': ['192.168.122.253', '192.168.122.254'], 'search-domain': 'ctlplane.example.local', 'mtu': 1500}}, 'group-templates': {'computes': {'network-template': {'range': {'start': 10, 'end': 15}}, 'networks': {'ctlplane': {}}}}})
2025-10-02 14:26:34.573945 | controller | ok: [instance] => (item={'networks': {'public': {'network-v4': '192.168.100.0/24'}}, 'group-templates': {'computes': {'networks': {'public': None}}}})
2025-10-02 14:26:34.574117 | controller |
2025-10-02 14:26:34.574262 | controller | TASK [networking_mapper : Gather facts if requested] ***************************
2025-10-02 14:26:34.574399 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.096)       0:00:56.631 ******
2025-10-02 14:26:34.591533 | controller | skipping: [instance]
2025-10-02 14:26:34.591587 | controller |
2025-10-02 14:26:34.591598 | controller | TASK [networking_mapper : Ensure CI infrastructure dir exists] *****************
2025-10-02 14:26:34.591661 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.018)       0:00:56.649 ******
2025-10-02 14:26:34.801103 | controller | ok: [instance]
2025-10-02 14:26:34.801145 | controller |
2025-10-02 14:26:34.801154 | controller | TASK [networking_mapper : Write the Networking Definition to file] *************
2025-10-02 14:26:34.801162 | controller | Thursday 02 October 2025  14:26:34 +0000 (0:00:00.209)       0:00:56.858 ******
2025-10-02 14:26:35.210924 | controller | changed: [instance]
2025-10-02 14:26:35.262169 | controller |
2025-10-02 14:26:35.262204 | controller | TASK [networking_mapper : Call the networking mapper] **************************
2025-10-02 14:26:35.262214 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.409)       0:00:57.268 ******
2025-10-02 14:26:35.262226 | controller | ok: [instance]
2025-10-02 14:26:35.262383 | controller |
2025-10-02 14:26:35.262419 | controller | TASK [networking_mapper : Set networking mapper facts] *************************
2025-10-02 14:26:35.285138 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.051)       0:00:57.320 ******
2025-10-02 14:26:35.285172 | controller | ok: [instance]
2025-10-02 14:26:35.285330 | controller |
2025-10-02 14:26:35.285350 | controller | TASK [networking_mapper : Write the Networking Environment Definition to file] ***
2025-10-02 14:26:35.704756 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.023)       0:00:57.343 ******
2025-10-02 14:26:35.704792 | controller | changed: [instance]
2025-10-02 14:26:35.704994 | controller |
2025-10-02 14:26:35.705047 | controller | TASK [libvirt_manager : Be sure to save current state of networking_mapper environment] ***
2025-10-02 14:26:35.726629 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.419)       0:00:57.762 ******
2025-10-02 14:26:35.726656 | controller | ok: [instance]
2025-10-02 14:26:35.726682 | controller |
2025-10-02 14:26:35.726691 | controller | TASK [libvirt_manager : Unset patch] *******************************************
2025-10-02 14:26:35.726841 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.021)       0:00:57.784 ******
2025-10-02 14:26:35.744780 | controller | ok: [instance]
2025-10-02 14:26:35.744871 | controller |
2025-10-02 14:26:35.745089 | controller | TASK [libvirt_manager : Initialize empty _lm_dhcp_entries fact] ****************
2025-10-02 14:26:35.763723 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.018)       0:00:57.802 ******
2025-10-02 14:26:35.763753 | controller | ok: [instance]
2025-10-02 14:26:35.801876 | controller |
2025-10-02 14:26:35.801907 | controller | TASK [libvirt_manager : Reserve IPs on networks] *******************************
2025-10-02 14:26:35.801915 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.018)       0:00:57.821 ******
2025-10-02 14:26:35.801925 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=ctlplane)
2025-10-02 14:26:35.868489 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/reserve_dnsmasq_ips.yml for instance => (item=public)
2025-10-02 14:26:35.868551 | controller |
2025-10-02 14:26:35.868561 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-02 14:26:35.868567 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.037)       0:00:57.859 ******
2025-10-02 14:26:35.868583 | controller | skipping: [instance] => (item=compute-0 - ctlplane)
2025-10-02 14:26:35.868622 | controller | skipping: [instance] => (item=compute-1 - ctlplane)
2025-10-02 14:26:35.868801 | controller | skipping: [instance]
2025-10-02 14:26:35.869087 | controller |
2025-10-02 14:26:35.869132 | controller | TASK [libvirt_manager : Loop on host IPs] **************************************
2025-10-02 14:26:35.966983 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.066)       0:00:57.926 ******
2025-10-02 14:26:35.967074 | controller | ok: [instance] => (item=compute-0 - public)
2025-10-02 14:26:36.023147 | controller | ok: [instance] => (item=compute-1 - public)
2025-10-02 14:26:36.023192 | controller |
2025-10-02 14:26:36.023203 | controller | TASK [Inject DHCP entries for net {{ net_name }}] ******************************
2025-10-02 14:26:36.023211 | controller | Thursday 02 October 2025  14:26:35 +0000 (0:00:00.097)       0:00:58.024 ******
2025-10-02 14:26:36.023224 | controller |
2025-10-02 14:26:36.064670 | controller | TASK [dnsmasq : Ensure we have the right data and type] ************************
2025-10-02 14:26:36.064724 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.056)       0:00:58.080 ******
2025-10-02 14:26:36.064741 | controller | ok: [instance]
2025-10-02 14:26:36.064945 | controller |
2025-10-02 14:26:36.065578 | controller | TASK [dnsmasq : Assert we have needed host data] *******************************
2025-10-02 14:26:36.066060 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.041)       0:00:58.121 ******
2025-10-02 14:26:36.134498 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:78:71:95', 'ips': ['192.168.100.10', '']})
2025-10-02 14:26:36.134538 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:8c:8e:ca', 'ips': ['192.168.100.11', '']})
2025-10-02 14:26:36.134549 | controller |
2025-10-02 14:26:36.134652 | controller | TASK [dnsmasq : Ensure networks exists] ****************************************
2025-10-02 14:26:36.134742 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.070)       0:00:58.192 ******
2025-10-02 14:26:36.179926 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/dnsmasq/tasks/_check_net_status.yml for instance => (item=public)
2025-10-02 14:26:36.179973 | controller |
2025-10-02 14:26:36.180116 | controller | TASK [dnsmasq : Check network file status] *************************************
2025-10-02 14:26:36.180222 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.045)       0:00:58.237 ******
2025-10-02 14:26:36.366462 | controller | ok: [instance]
2025-10-02 14:26:36.366528 | controller |
2025-10-02 14:26:36.366632 | controller | TASK [dnsmasq : Assert network exists] *****************************************
2025-10-02 14:26:36.366734 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.186)       0:00:58.424 ******
2025-10-02 14:26:36.388719 | controller | ok: [instance]
2025-10-02 14:26:36.388789 | controller |
2025-10-02 14:26:36.388908 | controller | TASK [dnsmasq : Initialize empty dhcp_host_entries] ****************************
2025-10-02 14:26:36.389026 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.022)       0:00:58.446 ******
2025-10-02 14:26:36.407275 | controller | ok: [instance]
2025-10-02 14:26:36.407352 | controller |
2025-10-02 14:26:36.407452 | controller | TASK [dnsmasq : Compute entry] *************************************************
2025-10-02 14:26:36.407555 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.018)       0:00:58.465 ******
2025-10-02 14:26:36.505334 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-0', 'state': 'present', 'mac': '52:54:00:78:71:95', 'ips': ['192.168.100.10', '']})
2025-10-02 14:26:36.505438 | controller | ok: [instance] => (item={'network': 'public', 'name': 'compute-1', 'state': 'present', 'mac': '52:54:01:8c:8e:ca', 'ips': ['192.168.100.11', '']})
2025-10-02 14:26:36.505541 | controller |
2025-10-02 14:26:36.505644 | controller | TASK [dnsmasq : Create add/remove sets] ****************************************
2025-10-02 14:26:36.505758 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.097)       0:00:58.563 ******
2025-10-02 14:26:36.545050 | controller | ok: [instance]
2025-10-02 14:26:36.545119 | controller |
2025-10-02 14:26:36.545240 | controller | TASK [dnsmasq : Add DHCP entries] **********************************************
2025-10-02 14:26:36.545339 | controller | Thursday 02 October 2025  14:26:36 +0000 (0:00:00.039)       0:00:58.603 ******
2025-10-02 14:26:37.261204 | controller | changed: [instance] => (item={'file': 'public_compute-0_52:54:00:78:71:95', 'entry': '52:54:00:78:71:95,192.168.100.10,compute-0', 'state': 'present'})
2025-10-02 14:26:37.261257 | controller | changed: [instance] => (item={'file': 'public_compute-1_52:54:01:8c:8e:ca', 'entry': '52:54:01:8c:8e:ca,192.168.100.11,compute-1', 'state': 'present'})
2025-10-02 14:26:37.261352 | controller |
2025-10-02 14:26:37.261458 | controller | TASK [dnsmasq : Remove DHCP entries] *******************************************
2025-10-02 14:26:37.261559 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.716)       0:00:59.319 ******
2025-10-02 14:26:37.284887 | controller | skipping: [instance]
2025-10-02 14:26:37.285008 | controller |
2025-10-02 14:26:37.285119 | controller | TASK [libvirt_manager : Create per-network and .utility DNS entries] ***********
2025-10-02 14:26:37.285218 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.023)       0:00:59.342 ******
2025-10-02 14:26:37.410842 | controller | ok: [instance] => (item=compute-0)
2025-10-02 14:26:37.410958 | controller | ok: [instance] => (item=compute-1)
2025-10-02 14:26:37.411111 | controller |
2025-10-02 14:26:37.411232 | controller | TASK [Inject VMs in the .utility zone] *****************************************
2025-10-02 14:26:37.411335 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.125)       0:00:59.468 ******
2025-10-02 14:26:37.471103 | controller |
2025-10-02 14:26:37.471159 | controller | TASK [dnsmasq : Assert we have needed host record data] ************************
2025-10-02 14:26:37.471298 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.060)       0:00:59.529 ******
2025-10-02 14:26:37.511544 | controller | ok: [instance]
2025-10-02 14:26:37.511589 | controller |
2025-10-02 14:26:37.511715 | controller | TASK [dnsmasq : Assert each address element have needed data] ******************
2025-10-02 14:26:37.511844 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.040)       0:00:59.569 ******
2025-10-02 14:26:37.610457 | controller | ok: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-02 14:26:37.610516 | controller | ok: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-02 14:26:37.610630 | controller | ok: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2025-10-02 14:26:37.610746 | controller | ok: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-10-02 14:26:37.610858 | controller | ok: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-10-02 14:26:37.610982 | controller | ok: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2025-10-02 14:26:37.611069 | controller |
2025-10-02 14:26:37.611190 | controller | TASK [dnsmasq : Add/Remove address] ********************************************
2025-10-02 14:26:37.611335 | controller | Thursday 02 October 2025  14:26:37 +0000 (0:00:00.098)       0:00:59.668 ******
2025-10-02 14:26:38.985196 | controller | changed: [instance] => (item={'names': ['compute-0.utility', 'compute-0.instance', 'compute-0.utility', 'compute-0.instance'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-02 14:26:38.985296 | controller | changed: [instance] => (item={'names': ['compute-0.ctlplane.local', 'compute-0.ctlplane.local'], 'ips': ['192.168.122.10', ''], 'state': 'present'})
2025-10-02 14:26:38.985408 | controller | changed: [instance] => (item={'names': ['compute-0.public.local', 'compute-0.public.local'], 'ips': ['192.168.100.10', ''], 'state': 'present'})
2025-10-02 14:26:38.985512 | controller | changed: [instance] => (item={'names': ['compute-1.utility', 'compute-1.instance', 'compute-1.utility', 'compute-1.instance'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-10-02 14:26:38.985630 | controller | changed: [instance] => (item={'names': ['compute-1.ctlplane.local', 'compute-1.ctlplane.local'], 'ips': ['192.168.122.11', ''], 'state': 'present'})
2025-10-02 14:26:38.985738 | controller | changed: [instance] => (item={'names': ['compute-1.public.local', 'compute-1.public.local'], 'ips': ['192.168.100.11', ''], 'state': 'present'})
2025-10-02 14:26:38.985834 | controller |
2025-10-02 14:26:38.985957 | controller | TASK [libvirt_manager : Ensure some domains are local] *************************
2025-10-02 14:26:38.986063 | controller | Thursday 02 October 2025  14:26:38 +0000 (0:00:01.374)       0:01:01.043 ******
2025-10-02 14:26:39.393382 | controller | changed: [instance]
2025-10-02 14:26:39.393480 | controller |
2025-10-02 14:26:39.393619 | controller | TASK [libvirt_manager : Ensure dnsmasq is reloaded now] ************************
2025-10-02 14:26:39.393739 | controller | Thursday 02 October 2025  14:26:39 +0000 (0:00:00.397)       0:01:01.440 ******
2025-10-02 14:26:39.393860 | controller |
2025-10-02 14:26:39.393972 | controller | RUNNING HANDLER [libvirt_manager : Restart firewalld] **************************
2025-10-02 14:26:39.394086 | controller | Thursday 02 October 2025  14:26:39 +0000 (0:00:00.010)       0:01:01.451 ******
2025-10-02 14:26:40.261051 | controller | changed: [instance]
2025-10-02 14:26:40.261179 | controller |
2025-10-02 14:26:40.261367 | controller | RUNNING HANDLER [dnsmasq : Restart dnsmasq] ************************************
2025-10-02 14:26:40.630798 | controller | Thursday 02 October 2025  14:26:40 +0000 (0:00:00.867)       0:01:02.318 ******
2025-10-02 14:26:40.630908 | controller | changed: [instance]
2025-10-02 14:26:42.039679 | controller |
2025-10-02 14:26:42.039719 | controller | RUNNING HANDLER [dnsmasq : Reload dnsmasq] *************************************
2025-10-02 14:26:42.039728 | controller | Thursday 02 October 2025  14:26:40 +0000 (0:00:00.369)       0:01:02.688 ******
2025-10-02 14:26:42.039740 | controller | changed: [instance]
2025-10-02 14:26:42.442146 | controller |
2025-10-02 14:26:42.442249 | controller | TASK [libvirt_manager : Create group inventories] ******************************
2025-10-02 14:26:42.442258 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:01.408)       0:01:04.097 ******
2025-10-02 14:26:42.442270 | controller | changed: [instance] => (item=compute)
2025-10-02 14:26:42.853061 | controller |
2025-10-02 14:26:42.853099 | controller | TASK [libvirt_manager : Create "all" group inventory file] *********************
2025-10-02 14:26:42.853107 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:00.402)       0:01:04.499 ******
2025-10-02 14:26:42.853118 | controller | changed: [instance]
2025-10-02 14:26:42.891381 | controller |
2025-10-02 14:26:42.891415 | controller | TASK [libvirt_manager : Ensure storage pool is present.] ***********************
2025-10-02 14:26:42.891423 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:00.410)       0:01:04.910 ******
2025-10-02 14:26:42.891434 | controller | skipping: [instance]
2025-10-02 14:26:42.891458 | controller |
2025-10-02 14:26:42.891466 | controller | TASK [libvirt_manager : Ensure images are present] *****************************
2025-10-02 14:26:42.891632 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:00.038)       0:01:04.949 ******
2025-10-02 14:26:42.969981 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/get_image.yml for instance => (item=compute)
2025-10-02 14:26:42.970060 | controller |
2025-10-02 14:26:42.970072 | controller | TASK [libvirt_manager : Ensure directory exists] *******************************
2025-10-02 14:26:42.970082 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:00.078)       0:01:05.027 ******
2025-10-02 14:26:42.989227 | controller | skipping: [instance]
2025-10-02 14:26:42.989319 | controller |
2025-10-02 14:26:42.989450 | controller | TASK [libvirt_manager : Check if base image exists] ****************************
2025-10-02 14:26:42.989599 | controller | Thursday 02 October 2025  14:26:42 +0000 (0:00:00.019)       0:01:05.047 ******
2025-10-02 14:26:43.008802 | controller | skipping: [instance]
2025-10-02 14:26:43.008928 | controller |
2025-10-02 14:26:43.009086 | controller | TASK [libvirt_manager : Download base image] ***********************************
2025-10-02 14:26:43.009217 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.019)       0:01:05.066 ******
2025-10-02 14:26:43.027797 | controller | skipping: [instance]
2025-10-02 14:26:43.027930 | controller |
2025-10-02 14:26:43.028147 | controller | TASK [libvirt_manager : Check image] *******************************************
2025-10-02 14:26:43.028310 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.019)       0:01:05.085 ******
2025-10-02 14:26:43.048987 | controller | skipping: [instance]
2025-10-02 14:26:43.049084 | controller |
2025-10-02 14:26:43.049192 | controller | TASK [libvirt_manager : Assert image status] ***********************************
2025-10-02 14:26:43.049305 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.021)       0:01:05.107 ******
2025-10-02 14:26:43.068251 | controller | skipping: [instance]
2025-10-02 14:26:43.068334 | controller |
2025-10-02 14:26:43.068469 | controller | TASK [libvirt_manager : Ensure image access rights] ****************************
2025-10-02 14:26:43.068588 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.019)       0:01:05.126 ******
2025-10-02 14:26:43.087750 | controller | skipping: [instance]
2025-10-02 14:26:43.087828 | controller |
2025-10-02 14:26:43.088000 | controller | TASK [libvirt_manager : Get ssh key state] *************************************
2025-10-02 14:26:43.088138 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.019)       0:01:05.145 ******
2025-10-02 14:26:43.270097 | controller | ok: [instance]
2025-10-02 14:26:43.270190 | controller |
2025-10-02 14:26:43.270315 | controller | TASK [libvirt_manager : Create temporary ssh keypair] **************************
2025-10-02 14:26:43.270406 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.182)       0:01:05.327 ******
2025-10-02 14:26:43.682424 | controller | changed: [instance]
2025-10-02 14:26:43.682475 | controller |
2025-10-02 14:26:43.682587 | controller | TASK [libvirt_manager : Slurp public key for later use] ************************
2025-10-02 14:26:43.682698 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.412)       0:01:05.740 ******
2025-10-02 14:26:43.965512 | controller | ok: [instance]
2025-10-02 14:26:43.965581 | controller |
2025-10-02 14:26:43.965709 | controller | TASK [libvirt_manager : Slurp private key for later use] ***********************
2025-10-02 14:26:43.965824 | controller | Thursday 02 October 2025  14:26:43 +0000 (0:00:00.279)       0:01:06.019 ******
2025-10-02 14:26:44.144583 | controller | ok: [instance]
2025-10-02 14:26:44.144653 | controller |
2025-10-02 14:26:44.144952 | controller | TASK [libvirt_manager : Inject cifmw_reproducer_key.pub in hypervisor authorized_keys] ***
2025-10-02 14:26:44.570696 | controller | Thursday 02 October 2025  14:26:44 +0000 (0:00:00.182)       0:01:06.202 ******
2025-10-02 14:26:44.570734 | controller | changed: [instance]
2025-10-02 14:26:44.570763 | controller |
2025-10-02 14:26:44.570772 | controller | TASK [libvirt_manager : Create fact holding network data for VMs] **************
2025-10-02 14:26:44.570893 | controller | Thursday 02 October 2025  14:26:44 +0000 (0:00:00.425)       0:01:06.628 ******
2025-10-02 14:26:44.591594 | controller | ok: [instance]
2025-10-02 14:26:44.833567 | controller |
2025-10-02 14:26:44.833609 | controller | TASK [libvirt_manager : List existing networks] ********************************
2025-10-02 14:26:44.833617 | controller | Thursday 02 October 2025  14:26:44 +0000 (0:00:00.021)       0:01:06.649 ******
2025-10-02 14:26:44.833629 | controller | ok: [instance]
2025-10-02 14:26:45.214821 | controller |
2025-10-02 14:26:45.214867 | controller | TASK [libvirt_manager : Gather pool fact] **************************************
2025-10-02 14:26:45.214876 | controller | Thursday 02 October 2025  14:26:44 +0000 (0:00:00.241)       0:01:06.891 ******
2025-10-02 14:26:45.214886 | controller | ok: [instance]
2025-10-02 14:26:45.296299 | controller |
2025-10-02 14:26:45.296346 | controller | TASK [libvirt_manager : Create and run VMs] ************************************
2025-10-02 14:26:45.296355 | controller | Thursday 02 October 2025  14:26:45 +0000 (0:00:00.381)       0:01:07.272 ******
2025-10-02 14:26:45.296366 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_vms.yml for instance => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-02 14:26:45.296384 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/create_vms.yml for instance => (item={'key': 'compute-1', 'value': 'compute'})
2025-10-02 14:26:45.296401 | controller |
2025-10-02 14:26:45.296442 | controller | TASK [libvirt_manager : Create VM image for compute-0] *************************
2025-10-02 14:26:45.296560 | controller | Thursday 02 October 2025  14:26:45 +0000 (0:00:00.081)       0:01:07.353 ******
2025-10-02 14:26:45.562395 | controller | changed: [instance]
2025-10-02 14:26:45.562470 | controller |
2025-10-02 14:26:45.562585 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-0] ********
2025-10-02 14:26:45.562691 | controller | Thursday 02 October 2025  14:26:45 +0000 (0:00:00.266)       0:01:07.620 ******
2025-10-02 14:26:45.814685 | controller | changed: [instance]
2025-10-02 14:26:45.814743 | controller |
2025-10-02 14:26:45.814859 | controller | TASK [libvirt_manager : Define VMs for type compute-0] *************************
2025-10-02 14:26:45.814964 | controller | Thursday 02 October 2025  14:26:45 +0000 (0:00:00.251)       0:01:07.872 ******
2025-10-02 14:26:46.219795 | controller | changed: [instance]
2025-10-02 14:26:46.219845 | controller |
2025-10-02 14:26:46.219854 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-0] ***********
2025-10-02 14:26:46.219862 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.405)       0:01:08.277 ******
2025-10-02 14:26:46.245856 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2025-10-02 14:26:46.283055 | controller |
2025-10-02 14:26:46.283091 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2025-10-02 14:26:46.283099 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.026)       0:01:08.303 ******
2025-10-02 14:26:46.283110 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2025-10-02 14:26:46.283155 | controller |
2025-10-02 14:26:46.283307 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2025-10-02 14:26:46.283374 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.037)       0:01:08.341 ******
2025-10-02 14:26:46.541136 | controller | ok: [instance]
2025-10-02 14:26:46.541246 | controller |
2025-10-02 14:26:46.541259 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2025-10-02 14:26:46.541372 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.257)       0:01:08.598 ******
2025-10-02 14:26:46.590502 | controller | ok: [instance] => (item=default)
2025-10-02 14:26:46.590627 | controller | ok: [instance] => (item=crc)
2025-10-02 14:26:46.590720 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:46.591887 | controller |
2025-10-02 14:26:46.592199 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2025-10-02 14:26:46.592291 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.049)       0:01:08.648 ******
2025-10-02 14:26:46.826139 | controller | ok: [instance]
2025-10-02 14:26:46.826227 | controller |
2025-10-02 14:26:46.826355 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2025-10-02 14:26:46.826459 | controller | Thursday 02 October 2025  14:26:46 +0000 (0:00:00.235)       0:01:08.884 ******
2025-10-02 14:26:47.033079 | controller | ok: [instance]
2025-10-02 14:26:47.333523 | controller |
2025-10-02 14:26:47.333554 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-0] ************
2025-10-02 14:26:47.333563 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.205)       0:01:09.089 ******
2025-10-02 14:26:47.333573 | controller | changed: [instance]
2025-10-02 14:26:47.333604 | controller |
2025-10-02 14:26:47.333614 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-0] *****
2025-10-02 14:26:47.333765 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.301)       0:01:09.391 ******
2025-10-02 14:26:47.353106 | controller | skipping: [instance]
2025-10-02 14:26:47.381520 | controller |
2025-10-02 14:26:47.381548 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-0] ********
2025-10-02 14:26:47.381556 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.019)       0:01:09.410 ******
2025-10-02 14:26:47.381566 | controller | skipping: [instance]
2025-10-02 14:26:47.381628 | controller |
2025-10-02 14:26:47.381644 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-0] **************
2025-10-02 14:26:47.381659 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.028)       0:01:09.439 ******
2025-10-02 14:26:47.408151 | controller | skipping: [instance]
2025-10-02 14:26:47.433884 | controller |
2025-10-02 14:26:47.433917 | controller | TASK [libvirt_manager : Attach volumes for VM compute-0] ***********************
2025-10-02 14:26:47.433926 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.026)       0:01:09.465 ******
2025-10-02 14:26:47.433938 | controller | skipping: [instance]
2025-10-02 14:26:47.656087 | controller |
2025-10-02 14:26:47.656127 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2025-10-02 14:26:47.656136 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.025)       0:01:09.491 ******
2025-10-02 14:26:47.656148 | controller | changed: [instance]
2025-10-02 14:26:47.656176 | controller |
2025-10-02 14:26:47.656403 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2025-10-02 14:26:47.718133 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.222)       0:01:09.713 ******
2025-10-02 14:26:47.718173 | controller | ok: [instance]
2025-10-02 14:26:47.718206 | controller |
2025-10-02 14:26:47.718217 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2025-10-02 14:26:47.718243 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.062)       0:01:09.776 ******
2025-10-02 14:26:47.738597 | controller | skipping: [instance]
2025-10-02 14:26:47.757141 | controller |
2025-10-02 14:26:47.757174 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2025-10-02 14:26:47.757184 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.020)       0:01:09.796 ******
2025-10-02 14:26:47.757196 | controller | skipping: [instance]
2025-10-02 14:26:47.757227 | controller |
2025-10-02 14:26:47.757443 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2025-10-02 14:26:47.800191 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.018)       0:01:09.815 ******
2025-10-02 14:26:47.800247 | controller | skipping: [instance]
2025-10-02 14:26:47.800269 | controller |
2025-10-02 14:26:47.800278 | controller | TASK [libvirt_manager : Create VM image for compute-1] *************************
2025-10-02 14:26:47.800382 | controller | Thursday 02 October 2025  14:26:47 +0000 (0:00:00.042)       0:01:09.858 ******
2025-10-02 14:26:48.041733 | controller | changed: [instance]
2025-10-02 14:26:48.041785 | controller |
2025-10-02 14:26:48.041868 | controller | TASK [libvirt_manager : Ensure file ownership and rights for compute-1] ********
2025-10-02 14:26:48.041984 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.241)       0:01:10.099 ******
2025-10-02 14:26:48.268787 | controller | changed: [instance]
2025-10-02 14:26:48.270835 | controller |
2025-10-02 14:26:48.560401 | controller | TASK [libvirt_manager : Define VMs for type compute-1] *************************
2025-10-02 14:26:48.560429 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.227)       0:01:10.326 ******
2025-10-02 14:26:48.560441 | controller | changed: [instance]
2025-10-02 14:26:48.560459 | controller |
2025-10-02 14:26:48.560467 | controller | TASK [libvirt_manager : Attach listed networks to the VMs compute-1] ***********
2025-10-02 14:26:48.560490 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.291)       0:01:10.618 ******
2025-10-02 14:26:48.584667 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/net_to_vms.yml for instance
2025-10-02 14:26:48.584733 | controller |
2025-10-02 14:26:48.584853 | controller | TASK [libvirt_manager : Attach {{ vm_item }} to {{ net_item }}] ****************
2025-10-02 14:26:48.584955 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.024)       0:01:10.642 ******
2025-10-02 14:26:48.617958 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/attach_interface.yml for instance => (item=public)
2025-10-02 14:26:48.618070 | controller |
2025-10-02 14:26:48.618239 | controller | TASK [libvirt_manager : Get virtual network information] ***********************
2025-10-02 14:26:48.867411 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.033)       0:01:10.676 ******
2025-10-02 14:26:48.867449 | controller | ok: [instance]
2025-10-02 14:26:48.867482 | controller |
2025-10-02 14:26:48.867591 | controller | TASK [libvirt_manager : Create network to bridge mapping] **********************
2025-10-02 14:26:48.867702 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.249)       0:01:10.925 ******
2025-10-02 14:26:48.918328 | controller | ok: [instance] => (item=default)
2025-10-02 14:26:48.918451 | controller | ok: [instance] => (item=crc)
2025-10-02 14:26:48.918574 | controller | ok: [instance] => (item=cifmw-public)
2025-10-02 14:26:48.918697 | controller |
2025-10-02 14:26:48.918806 | controller | TASK [libvirt_manager : Dump domain xml] ***************************************
2025-10-02 14:26:48.918950 | controller | Thursday 02 October 2025  14:26:48 +0000 (0:00:00.051)       0:01:10.976 ******
2025-10-02 14:26:49.159164 | controller | ok: [instance]
2025-10-02 14:26:49.159254 | controller |
2025-10-02 14:26:49.159377 | controller | TASK [libvirt_manager : Extract networks from XML] *****************************
2025-10-02 14:26:49.159480 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.240)       0:01:11.217 ******
2025-10-02 14:26:49.362963 | controller | ok: [instance]
2025-10-02 14:26:49.363039 | controller |
2025-10-02 14:26:49.363155 | controller | TASK [libvirt_manager : Attach interface public on cifmw-compute-1] ************
2025-10-02 14:26:49.363255 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.203)       0:01:11.420 ******
2025-10-02 14:26:49.660093 | controller | changed: [instance]
2025-10-02 14:26:49.660182 | controller |
2025-10-02 14:26:49.660292 | controller | TASK [libvirt_manager : Attach spines/leafs networks to the VMs compute-1] *****
2025-10-02 14:26:49.660402 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.297)       0:01:11.718 ******
2025-10-02 14:26:49.680919 | controller | skipping: [instance]
2025-10-02 14:26:49.681027 | controller |
2025-10-02 14:26:49.681167 | controller | TASK [libvirt_manager : Create the requested extra disks for compute-1] ********
2025-10-02 14:26:49.681295 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.020)       0:01:11.738 ******
2025-10-02 14:26:49.712577 | controller | skipping: [instance]
2025-10-02 14:26:49.712641 | controller |
2025-10-02 14:26:49.712741 | controller | TASK [libvirt_manager : Find volume attachments for VM compute-1] **************
2025-10-02 14:26:49.712854 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.031)       0:01:11.770 ******
2025-10-02 14:26:49.740322 | controller | skipping: [instance]
2025-10-02 14:26:49.740403 | controller |
2025-10-02 14:26:49.740523 | controller | TASK [libvirt_manager : Attach volumes for VM compute-1] ***********************
2025-10-02 14:26:49.740619 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.027)       0:01:11.798 ******
2025-10-02 14:26:49.768271 | controller | skipping: [instance]
2025-10-02 14:26:49.768354 | controller |
2025-10-02 14:26:49.768492 | controller | TASK [libvirt_manager : Get VM UUID] *******************************************
2025-10-02 14:26:49.768603 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.027)       0:01:11.826 ******
2025-10-02 14:26:49.989126 | controller | changed: [instance]
2025-10-02 14:26:49.989186 | controller |
2025-10-02 14:26:49.989302 | controller | TASK [libvirt_manager : Inject UUID in dataset] ********************************
2025-10-02 14:26:49.989403 | controller | Thursday 02 October 2025  14:26:49 +0000 (0:00:00.220)       0:01:12.047 ******
2025-10-02 14:26:50.026962 | controller | ok: [instance]
2025-10-02 14:26:50.027066 | controller |
2025-10-02 14:26:50.027171 | controller | TASK [libvirt_manager : Create cloud-init ISO] *********************************
2025-10-02 14:26:50.027271 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.037)       0:01:12.085 ******
2025-10-02 14:26:50.046291 | controller | skipping: [instance]
2025-10-02 14:26:50.046380 | controller |
2025-10-02 14:26:50.046514 | controller | TASK [libvirt_manager : Attach cloud-init ISO if exists] ***********************
2025-10-02 14:26:50.046633 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.019)       0:01:12.104 ******
2025-10-02 14:26:50.065238 | controller | skipping: [instance]
2025-10-02 14:26:50.065311 | controller |
2025-10-02 14:26:50.065413 | controller | TASK [libvirt_manager : Attach additional devices if specified] ****************
2025-10-02 14:26:50.065506 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.018)       0:01:12.123 ******
2025-10-02 14:26:50.109820 | controller | skipping: [instance]
2025-10-02 14:26:50.109929 | controller |
2025-10-02 14:26:50.110077 | controller | TASK [libvirt_manager : Start (power-on) VMs] **********************************
2025-10-02 14:26:50.110205 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.044)       0:01:12.167 ******
2025-10-02 14:26:50.149959 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/start_vms.yml for instance
2025-10-02 14:26:50.150091 | controller |
2025-10-02 14:26:50.150214 | controller | TASK [libvirt_manager : Refresh oooq_pool before starting VMs] *****************
2025-10-02 14:26:50.150325 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.040)       0:01:12.208 ******
2025-10-02 14:26:50.400398 | controller | ok: [instance] => (item=crc)
2025-10-02 14:26:50.400438 | controller |
2025-10-02 14:26:50.400574 | controller | TASK [libvirt_manager : Start VMs for type {{ vm_type }}] **********************
2025-10-02 14:26:50.400678 | controller | Thursday 02 October 2025  14:26:50 +0000 (0:00:00.250)       0:01:12.458 ******
2025-10-02 14:26:51.449975 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-02 14:26:51.450041 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-10-02 14:26:51.450127 | controller | skipping: [instance]
2025-10-02 14:26:51.450365 | controller |
2025-10-02 14:26:51.450539 | controller | TASK [libvirt_manager : Wait for SSH on started VMs] ***************************
2025-10-02 14:26:51.450560 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:01.049)       0:01:13.507 ******
2025-10-02 14:26:51.505323 | controller | skipping: [instance] => (item=compute-0.utility)
2025-10-02 14:26:51.505366 | controller | skipping: [instance] => (item=compute-1.utility)
2025-10-02 14:26:51.505374 | controller | skipping: [instance]
2025-10-02 14:26:51.505383 | controller |
2025-10-02 14:26:51.505504 | controller | TASK [libvirt_manager : Ensure we get SSH on nodes] ****************************
2025-10-02 14:26:51.505622 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:00.055)       0:01:13.562 ******
2025-10-02 14:26:51.534399 | controller | skipping: [instance] => (item={'changed': False, 'skipped': True, 'skip_reason': 'Conditional result was False', 'false_condition': "vm_data.disk_file_name != 'blank'", '_vm': {'key': 'compute-0', 'value': 'compute'}, 'ansible_loop_var': '_vm'})
2025-10-02 14:26:51.534456 | controller | skipping: [instance] => (item={'changed': False, 'skipped': True, 'skip_reason': 'Conditional result was False', 'false_condition': "vm_data.disk_file_name != 'blank'", '_vm': {'key': 'compute-1', 'value': 'compute'}, 'ansible_loop_var': '_vm'})
2025-10-02 14:26:51.534573 | controller | skipping: [instance]
2025-10-02 14:26:51.534664 | controller |
2025-10-02 14:26:51.534758 | controller | TASK [libvirt_manager : Configure managed VMs] *********************************
2025-10-02 14:26:51.534890 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:00.029)       0:01:13.592 ******
2025-10-02 14:26:51.579129 | controller | skipping: [instance] => (item={'key': 'compute-0', 'value': 'compute'})
2025-10-02 14:26:51.579191 | controller | skipping: [instance] => (item={'key': 'compute-1', 'value': 'compute'})
2025-10-02 14:26:51.579282 | controller | skipping: [instance]
2025-10-02 14:26:51.579371 | controller |
2025-10-02 14:26:51.579470 | controller | TASK [Create VBMC entity] ******************************************************
2025-10-02 14:26:51.579550 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:00.044)       0:01:13.636 ******
2025-10-02 14:26:51.621152 | controller | skipping: [instance] => (item=compute-0)
2025-10-02 14:26:51.621206 | controller | skipping: [instance] => (item=compute-1)
2025-10-02 14:26:51.621327 | controller | skipping: [instance]
2025-10-02 14:26:51.621418 | controller |
2025-10-02 14:26:51.621519 | controller | TASK [libvirt_manager : List running virtual machines.] ************************
2025-10-02 14:26:51.621767 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:00.042)       0:01:13.679 ******
2025-10-02 14:26:51.875758 | controller | ok: [instance]
2025-10-02 14:26:51.875805 | controller |
2025-10-02 14:26:51.875939 | controller | TASK [libvirt_manager : Dump UUIDs] ********************************************
2025-10-02 14:26:51.876038 | controller | Thursday 02 October 2025  14:26:51 +0000 (0:00:00.254)       0:01:13.933 ******
2025-10-02 14:26:52.255899 | controller | changed: [instance]
2025-10-02 14:26:52.255964 | controller |
2025-10-02 14:26:52.256093 | controller | TASK [Ensure fresh vbmc listing] ***********************************************
2025-10-02 14:26:52.256194 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.380)       0:01:14.313 ******
2025-10-02 14:26:52.287147 | controller | skipping: [instance]
2025-10-02 14:26:52.287190 | controller |
2025-10-02 14:26:52.287198 | controller | TASK [libvirt_manager : Update vbmc related fact] ******************************
2025-10-02 14:26:52.287206 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.031)       0:01:14.345 ******
2025-10-02 14:26:52.316557 | controller | skipping: [instance]
2025-10-02 14:26:52.316604 | controller |
2025-10-02 14:26:52.316726 | controller | TASK [libvirt_manager : Dump vbmc known hosts] *********************************
2025-10-02 14:26:52.316821 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.029)       0:01:14.374 ******
2025-10-02 14:26:52.346577 | controller | skipping: [instance]
2025-10-02 14:26:52.346709 | controller |
2025-10-02 14:26:52.346770 | controller | TASK [libvirt_manager : Copy authorized_keys] **********************************
2025-10-02 14:26:52.346884 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.029)       0:01:14.404 ******
2025-10-02 14:26:52.374269 | controller | skipping: [instance]
2025-10-02 14:26:52.374334 | controller |
2025-10-02 14:26:52.374448 | controller | TASK [libvirt_manager : Enable root access on CRC] *****************************
2025-10-02 14:26:52.374548 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.027)       0:01:14.432 ******
2025-10-02 14:26:52.407352 | controller | skipping: [instance]
2025-10-02 14:26:52.407447 | controller |
2025-10-02 14:26:52.407589 | controller | TASK [Generate baremetal-info fact] ********************************************
2025-10-02 14:26:52.407671 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.033)       0:01:14.465 ******
2025-10-02 14:26:52.475697 | controller |
2025-10-02 14:26:52.475773 | controller | TASK [reproducer : Ensure directories exist] ***********************************
2025-10-02 14:26:52.475885 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.068)       0:01:14.533 ******
2025-10-02 14:26:52.881553 | controller | changed: [instance] => (item=parameters)
2025-10-02 14:26:52.881612 | controller | ok: [instance] => (item=artifacts)
2025-10-02 14:26:52.881699 | controller |
2025-10-02 14:26:52.881799 | controller | TASK [reproducer : Convert VBMC list into a dict for better usage] *************
2025-10-02 14:26:52.881925 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.405)       0:01:14.939 ******
2025-10-02 14:26:52.915254 | controller | skipping: [instance]
2025-10-02 14:26:52.915350 | controller |
2025-10-02 14:26:52.915421 | controller | TASK [reproducer : Check if baremetal-info.yml exists] *************************
2025-10-02 14:26:52.915531 | controller | Thursday 02 October 2025  14:26:52 +0000 (0:00:00.033)       0:01:14.973 ******
2025-10-02 14:26:53.113391 | controller | ok: [instance]
2025-10-02 14:26:53.113437 | controller |
2025-10-02 14:26:53.113537 | controller | TASK [reproducer : Get content of baremetal-info file] *************************
2025-10-02 14:26:53.113646 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.197)       0:01:15.171 ******
2025-10-02 14:26:53.132725 | controller | skipping: [instance]
2025-10-02 14:26:53.132882 | controller |
2025-10-02 14:26:53.132989 | controller | TASK [reproducer : Interpret remote file content as yaml] **********************
2025-10-02 14:26:53.133113 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.019)       0:01:15.190 ******
2025-10-02 14:26:53.163364 | controller | skipping: [instance]
2025-10-02 14:26:53.163487 | controller |
2025-10-02 14:26:53.163608 | controller | TASK [reproducer : Slurp content of: /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2025-10-02 14:26:53.163723 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.030)       0:01:15.221 ******
2025-10-02 14:26:53.190103 | controller | skipping: [instance]
2025-10-02 14:26:53.190210 | controller |
2025-10-02 14:26:53.190316 | controller | TASK [reproducer : Set cifmw_libvirt_manager_mac_map fact from /home/zuul/ci-framework-data/artifacts/interfaces-info.yml] ***
2025-10-02 14:26:53.190416 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.026)       0:01:15.248 ******
2025-10-02 14:26:53.215563 | controller | skipping: [instance]
2025-10-02 14:26:53.215659 | controller |
2025-10-02 14:26:53.215800 | controller | TASK [reproducer : Generate libvirt_manager_bm_info_data fact] *****************
2025-10-02 14:26:53.215941 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.025)       0:01:15.273 ******
2025-10-02 14:26:53.286249 | controller | ok: [instance] => (item={'key': 'cifmw-compute-0', 'value': '1b5dbafc-50eb-41fa-8629-9e9eacd521f4'})
2025-10-02 14:26:53.286374 | controller | ok: [instance] => (item={'key': 'cifmw-compute-1', 'value': '8c40e17f-cb95-4fa5-9e67-d663e3fe4bb0'})
2025-10-02 14:26:53.286461 | controller |
2025-10-02 14:26:53.286563 | controller | TASK [reproducer : Output baremetal info file] *********************************
2025-10-02 14:26:53.286693 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.070)       0:01:15.344 ******
2025-10-02 14:26:53.657095 | controller | changed: [instance]
2025-10-02 14:26:53.657153 | controller |
2025-10-02 14:26:53.657347 | controller | TASK [reproducer : Output ironic_nodes to file] ********************************
2025-10-02 14:26:53.657397 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.370)       0:01:15.715 ******
2025-10-02 14:26:53.707172 | controller | skipping: [instance]
2025-10-02 14:26:53.772338 | controller |
2025-10-02 14:26:53.772369 | controller | TASK [Run Sushy Emulator role against OCP] *************************************
2025-10-02 14:26:53.772377 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.049)       0:01:15.764 ******
2025-10-02 14:26:53.772387 | controller |
2025-10-02 14:26:53.978142 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] ***************
2025-10-02 14:26:53.978177 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.065)       0:01:15.830 ******
2025-10-02 14:26:53.978210 | controller | changed: [instance]
2025-10-02 14:26:53.978263 | controller |
2025-10-02 14:26:53.978283 | controller | TASK [sushy_emulator : Install required packages] ******************************
2025-10-02 14:26:53.978310 | controller | Thursday 02 October 2025  14:26:53 +0000 (0:00:00.205)       0:01:16.035 ******
2025-10-02 14:26:58.003326 | controller | changed: [instance]
2025-10-02 14:26:58.003379 | controller |
2025-10-02 14:26:58.003637 | controller | TASK [sushy_emulator : Get ingresses domain] ***********************************
2025-10-02 14:26:58.631131 | controller | Thursday 02 October 2025  14:26:58 +0000 (0:00:04.025)       0:01:20.061 ******
2025-10-02 14:26:58.631182 | controller | changed: [instance]
2025-10-02 14:26:58.631301 | controller |
2025-10-02 14:26:58.631329 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] *********************
2025-10-02 14:26:58.631338 | controller | Thursday 02 October 2025  14:26:58 +0000 (0:00:00.627)       0:01:20.688 ******
2025-10-02 14:26:58.659287 | controller | ok: [instance]
2025-10-02 14:26:58.659492 | controller |
2025-10-02 14:26:58.659527 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] **********************
2025-10-02 14:26:58.949037 | controller | Thursday 02 October 2025  14:26:58 +0000 (0:00:00.028)       0:01:20.717 ******
2025-10-02 14:26:58.949078 | controller | changed: [instance]
2025-10-02 14:26:59.147915 | controller |
2025-10-02 14:26:59.147945 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ********************
2025-10-02 14:26:59.147960 | controller | Thursday 02 October 2025  14:26:58 +0000 (0:00:00.285)       0:01:21.003 ******
2025-10-02 14:26:59.147971 | controller | ok: [instance]
2025-10-02 14:27:00.377842 | controller |
2025-10-02 14:27:00.377893 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] *******************************
2025-10-02 14:27:00.377902 | controller | Thursday 02 October 2025  14:26:59 +0000 (0:00:00.198)       0:01:21.202 ******
2025-10-02 14:27:00.377913 | controller | changed: [instance -> controller-0(192.168.25.200)]
2025-10-02 14:27:00.639600 | controller |
2025-10-02 14:27:00.639641 | controller | TASK [sushy_emulator : Run ssh-keyscan] ****************************************
2025-10-02 14:27:00.639651 | controller | Thursday 02 October 2025  14:27:00 +0000 (0:00:01.233)       0:01:22.435 ******
2025-10-02 14:27:00.639672 | controller | changed: [instance]
2025-10-02 14:27:00.996656 | controller |
2025-10-02 14:27:00.996706 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************
2025-10-02 14:27:00.996715 | controller | Thursday 02 October 2025  14:27:00 +0000 (0:00:00.261)       0:01:22.696 ******
2025-10-02 14:27:00.996727 | controller | changed: [instance]
2025-10-02 14:27:00.996750 | controller |
2025-10-02 14:27:00.996911 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:27:00.996942 | controller | Thursday 02 October 2025  14:27:00 +0000 (0:00:00.357)       0:01:23.054 ******
2025-10-02 14:27:01.026147 | controller | skipping: [instance]
2025-10-02 14:27:01.053116 | controller |
2025-10-02 14:27:01.053153 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:27:01.053186 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.029)       0:01:23.083 ******
2025-10-02 14:27:01.053199 | controller | skipping: [instance]
2025-10-02 14:27:01.053288 | controller |
2025-10-02 14:27:01.053375 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:27:01.053407 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.027)       0:01:23.111 ******
2025-10-02 14:27:01.078319 | controller | skipping: [instance]
2025-10-02 14:27:01.078401 | controller |
2025-10-02 14:27:01.078584 | controller | TASK [sushy_emulator : Generate list of filtered VMs] **************************
2025-10-02 14:27:01.078721 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.025)       0:01:23.136 ******
2025-10-02 14:27:01.114911 | controller | ok: [instance]
2025-10-02 14:27:01.115046 | controller |
2025-10-02 14:27:01.115091 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] ***************************
2025-10-02 14:27:01.115104 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.036)       0:01:23.172 ******
2025-10-02 14:27:01.132717 | controller | skipping: [instance]
2025-10-02 14:27:01.133069 | controller |
2025-10-02 14:27:01.133113 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ********
2025-10-02 14:27:01.150103 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.018)       0:01:23.190 ******
2025-10-02 14:27:01.150142 | controller | skipping: [instance]
2025-10-02 14:27:01.166942 | controller |
2025-10-02 14:27:01.166971 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] ***************
2025-10-02 14:27:01.166978 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.017)       0:01:23.208 ******
2025-10-02 14:27:01.166989 | controller | skipping: [instance]
2025-10-02 14:27:01.362791 | controller |
2025-10-02 14:27:01.362831 | controller | TASK [sushy_emulator : Generate htpasswd string] *******************************
2025-10-02 14:27:01.362840 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.016)       0:01:23.224 ******
2025-10-02 14:27:01.362853 | controller | changed: [instance]
2025-10-02 14:27:01.362982 | controller |
2025-10-02 14:27:01.362995 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] *********************
2025-10-02 14:27:01.363191 | controller | Thursday 02 October 2025  14:27:01 +0000 (0:00:00.195)       0:01:23.420 ******
2025-10-02 14:27:03.265312 | controller | changed: [instance] => (item=secret)
2025-10-02 14:27:03.265370 | controller | changed: [instance] => (item=configmap)
2025-10-02 14:27:03.265463 | controller | changed: [instance] => (item=pod)
2025-10-02 14:27:03.265575 | controller | changed: [instance] => (item=service)
2025-10-02 14:27:03.265671 | controller | changed: [instance] => (item=route)
2025-10-02 14:27:03.265797 | controller |
2025-10-02 14:27:03.265917 | controller | TASK [sushy_emulator : Write sushy emulator config] ****************************
2025-10-02 14:27:03.266050 | controller | Thursday 02 October 2025  14:27:03 +0000 (0:00:01.902)       0:01:25.323 ******
2025-10-02 14:27:03.287056 | controller | skipping: [instance]
2025-10-02 14:27:03.287197 | controller |
2025-10-02 14:27:03.287290 | controller | TASK [sushy_emulator : Write htpasswd string to file] **************************
2025-10-02 14:27:03.287395 | controller | Thursday 02 October 2025  14:27:03 +0000 (0:00:00.021)       0:01:25.344 ******
2025-10-02 14:27:03.312587 | controller | skipping: [instance]
2025-10-02 14:27:03.312692 | controller |
2025-10-02 14:27:03.312822 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ********************
2025-10-02 14:27:03.312954 | controller | Thursday 02 October 2025  14:27:03 +0000 (0:00:00.025)       0:01:25.370 ******
2025-10-02 14:27:04.235376 | controller | changed: [instance]
2025-10-02 14:27:04.235478 | controller |
2025-10-02 14:27:04.235615 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] ***
2025-10-02 14:27:04.235761 | controller | Thursday 02 October 2025  14:27:04 +0000 (0:00:00.922)       0:01:26.292 ******
2025-10-02 14:30:15.685722 | controller | ok: [instance]
2025-10-02 14:30:15.685846 | controller |
2025-10-02 14:30:15.685880 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] *************************
2025-10-02 14:30:15.685890 | controller | Thursday 02 October 2025  14:30:15 +0000 (0:03:11.450)       0:04:37.743 ******
2025-10-02 14:30:18.367142 | controller | changed: [instance] => (item=secret)
2025-10-02 14:30:18.367197 | controller | changed: [instance] => (item=configmap)
2025-10-02 14:30:18.367206 | controller | changed: [instance] => (item=service)
2025-10-02 14:30:18.367212 | controller | changed: [instance] => (item=route)
2025-10-02 14:30:18.367218 | controller |
2025-10-02 14:30:18.367223 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] **********************
2025-10-02 14:30:18.367232 | controller | Thursday 02 October 2025  14:30:18 +0000 (0:00:02.681)       0:04:40.424 ******
2025-10-02 14:30:49.075440 | controller | [WARNING]: unknown field "spec.selector"
2025-10-02 14:30:49.076214 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.076516 | controller | "spec.containers[0].readinessProbe.httpGet.initialDelaySeconds"
2025-10-02 14:30:49.076529 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.076953 | controller | "spec.containers[0].readinessProbe.httpGet.periodSeconds"
2025-10-02 14:30:49.076963 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.077571 | controller | "spec.containers[0].livenessProbe.httpGet.initialDelaySeconds"
2025-10-02 14:30:49.077596 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.077883 | controller | "spec.containers[0].livenessProbe.httpGet.failureThreshold"
2025-10-02 14:30:49.077893 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.078302 | controller | "spec.containers[0].livenessProbe.httpGet.periodSeconds"
2025-10-02 14:30:49.078324 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.078803 | controller | "spec.containers[0].startupProbe.httpGet.failureThreshold"
2025-10-02 14:30:49.078822 | controller | [WARNING]: unknown field
2025-10-02 14:30:49.087160 | controller | "spec.containers[0].startupProbe.httpGet.initialDelaySeconds"
2025-10-02 14:30:49.087221 | controller | changed: [instance]
2025-10-02 14:30:49.087250 | controller |
2025-10-02 14:30:49.087289 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-10-02 14:30:49.087425 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:30.720)       0:05:11.145 ******
2025-10-02 14:30:49.107321 | controller | skipping: [instance]
2025-10-02 14:30:49.107395 | controller |
2025-10-02 14:30:49.107499 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-10-02 14:30:49.107615 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.020)       0:05:11.165 ******
2025-10-02 14:30:49.131671 | controller | skipping: [instance]
2025-10-02 14:30:49.156634 | controller |
2025-10-02 14:30:49.156654 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-10-02 14:30:49.156663 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.024)       0:05:11.189 ******
2025-10-02 14:30:49.156673 | controller | skipping: [instance]
2025-10-02 14:30:49.176562 | controller |
2025-10-02 14:30:49.176595 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-10-02 14:30:49.176603 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.024)       0:05:11.214 ******
2025-10-02 14:30:49.176614 | controller | skipping: [instance]
2025-10-02 14:30:49.176638 | controller |
2025-10-02 14:30:49.176646 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-10-02 14:30:49.176777 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.020)       0:05:11.234 ******
2025-10-02 14:30:49.200881 | controller | skipping: [instance]
2025-10-02 14:30:49.201002 | controller |
2025-10-02 14:30:49.201067 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ********************
2025-10-02 14:30:49.201082 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.024)       0:05:11.258 ******
2025-10-02 14:30:49.219446 | controller | skipping: [instance]
2025-10-02 14:30:49.244889 | controller |
2025-10-02 14:30:49.244910 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] **************
2025-10-02 14:30:49.244919 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.018)       0:05:11.277 ******
2025-10-02 14:30:49.244929 | controller | skipping: [instance]
2025-10-02 14:30:49.305186 | controller |
2025-10-02 14:30:49.305238 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] *******************
2025-10-02 14:30:49.305247 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.025)       0:05:11.302 ******
2025-10-02 14:30:49.305259 | controller |
2025-10-02 14:30:49.337093 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] ***
2025-10-02 14:30:49.337122 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.060)       0:05:11.362 ******
2025-10-02 14:30:49.337135 | controller | ok: [instance]
2025-10-02 14:30:49.367647 | controller |
2025-10-02 14:30:49.367670 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-10-02 14:30:49.367679 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.031)       0:05:11.394 ******
2025-10-02 14:30:49.367690 | controller | skipping: [instance]
2025-10-02 14:30:49.398081 | controller |
2025-10-02 14:30:49.398099 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-10-02 14:30:49.398107 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.030)       0:05:11.425 ******
2025-10-02 14:30:49.398116 | controller | skipping: [instance]
2025-10-02 14:30:50.507609 | controller |
2025-10-02 14:30:50.507640 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] ***
2025-10-02 14:30:50.507648 | controller | Thursday 02 October 2025  14:30:49 +0000 (0:00:00.030)       0:05:11.455 ******
2025-10-02 14:30:50.507659 | controller | ok: [instance]
2025-10-02 14:30:52.999608 | controller |
2025-10-02 14:30:52.999640 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] ***
2025-10-02 14:30:52.999648 | controller | Thursday 02 October 2025  14:30:50 +0000 (0:00:01.109)       0:05:12.565 ******
2025-10-02 14:30:52.999658 | controller | ok: [instance] => (item=1b5dbafc-50eb-41fa-8629-9e9eacd521f4)
2025-10-02 14:30:53.049897 | controller | ok: [instance] => (item=8c40e17f-cb95-4fa5-9e67-d663e3fe4bb0)
2025-10-02 14:30:53.049931 | controller |
2025-10-02 14:30:53.049939 | controller | TASK [sushy_emulator : Verify baremetal VM power status] ***********************
2025-10-02 14:30:53.049945 | controller | Thursday 02 October 2025  14:30:52 +0000 (0:00:02.491)       0:05:15.057 ******
2025-10-02 14:30:53.049955 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-02 14:30:53.139130 | controller | ok: [instance] => (item=cifmw-compute-1)
2025-10-02 14:30:53.139157 | controller |
2025-10-02 14:30:53.139164 | controller | TASK [Run Sushy Emulator role against podman] **********************************
2025-10-02 14:30:53.139171 | controller | Thursday 02 October 2025  14:30:53 +0000 (0:00:00.050)       0:05:15.107 ******
2025-10-02 14:30:53.139180 | controller |
2025-10-02 14:30:53.339551 | controller | TASK [sushy_emulator : Create Sushy Emulator resource directory] ***************
2025-10-02 14:30:53.339594 | controller | Thursday 02 October 2025  14:30:53 +0000 (0:00:00.089)       0:05:15.197 ******
2025-10-02 14:30:53.339607 | controller | ok: [instance]
2025-10-02 14:30:54.607968 | controller |
2025-10-02 14:30:54.608000 | controller | TASK [sushy_emulator : Install required packages] ******************************
2025-10-02 14:30:54.608058 | controller | Thursday 02 October 2025  14:30:53 +0000 (0:00:00.200)       0:05:15.397 ******
2025-10-02 14:30:54.608077 | controller | ok: [instance]
2025-10-02 14:30:54.627115 | controller |
2025-10-02 14:30:54.627139 | controller | TASK [sushy_emulator : Get ingresses domain] ***********************************
2025-10-02 14:30:54.627153 | controller | Thursday 02 October 2025  14:30:54 +0000 (0:00:01.268)       0:05:16.665 ******
2025-10-02 14:30:54.627165 | controller | skipping: [instance]
2025-10-02 14:30:54.627194 | controller |
2025-10-02 14:30:54.627204 | controller | TASK [sushy_emulator : Set sushy url for ocp installation] *********************
2025-10-02 14:30:54.627331 | controller | Thursday 02 October 2025  14:30:54 +0000 (0:00:00.019)       0:05:16.685 ******
2025-10-02 14:30:54.646564 | controller | skipping: [instance]
2025-10-02 14:30:54.905591 | controller |
2025-10-02 14:30:54.905626 | controller | TASK [sushy_emulator : Create ssh key for Sushy Emulator] **********************
2025-10-02 14:30:54.905634 | controller | Thursday 02 October 2025  14:30:54 +0000 (0:00:00.019)       0:05:16.704 ******
2025-10-02 14:30:54.905645 | controller | ok: [instance]
2025-10-02 14:30:55.082061 | controller |
2025-10-02 14:30:55.082108 | controller | TASK [sushy_emulator : Slurp private ssh key for later use] ********************
2025-10-02 14:30:55.082117 | controller | Thursday 02 October 2025  14:30:54 +0000 (0:00:00.258)       0:05:16.963 ******
2025-10-02 14:30:55.082128 | controller | ok: [instance]
2025-10-02 14:30:55.082151 | controller |
2025-10-02 14:30:55.082409 | controller | TASK [sushy_emulator : Allow Sushy Emulator key] *******************************
2025-10-02 14:30:56.230104 | controller | Thursday 02 October 2025  14:30:55 +0000 (0:00:00.176)       0:05:17.140 ******
2025-10-02 14:30:56.230147 | controller | ok: [instance -> controller-0(192.168.25.200)]
2025-10-02 14:30:56.230167 | controller |
2025-10-02 14:30:56.230326 | controller | TASK [sushy_emulator : Run ssh-keyscan] ****************************************
2025-10-02 14:30:56.230435 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:01.147)       0:05:18.287 ******
2025-10-02 14:30:56.467108 | controller | changed: [instance]
2025-10-02 14:30:56.467260 | controller |
2025-10-02 14:30:56.467293 | controller | TASK [sushy_emulator : Write known hosts for later use] ************************
2025-10-02 14:30:56.467305 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.237)       0:05:18.524 ******
2025-10-02 14:30:56.832518 | controller | changed: [instance]
2025-10-02 14:30:56.859942 | controller |
2025-10-02 14:30:56.860003 | controller | TASK [sushy_emulator : Ensure file exists: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:30:56.860036 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.365)       0:05:18.890 ******
2025-10-02 14:30:56.860053 | controller | skipping: [instance]
2025-10-02 14:30:56.860127 | controller |
2025-10-02 14:30:56.860171 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:30:56.887817 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.027)       0:05:18.917 ******
2025-10-02 14:30:56.887852 | controller | skipping: [instance]
2025-10-02 14:30:56.910474 | controller |
2025-10-02 14:30:56.910501 | controller | TASK [sushy_emulator : Set cifmw_libvirt_manager_uuids fact from /home/zuul/ci-framework-data/artifacts/libvirt-uuids.yml] ***
2025-10-02 14:30:56.910509 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.027)       0:05:18.945 ******
2025-10-02 14:30:56.910520 | controller | skipping: [instance]
2025-10-02 14:30:56.910545 | controller |
2025-10-02 14:30:56.910551 | controller | TASK [sushy_emulator : Generate list of filtered VMs] **************************
2025-10-02 14:30:56.910558 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.023)       0:05:18.968 ******
2025-10-02 14:30:56.946918 | controller | ok: [instance]
2025-10-02 14:30:56.946970 | controller |
2025-10-02 14:30:56.947202 | controller | TASK [sushy_emulator : Get Openstack instance UUIDs] ***************************
2025-10-02 14:30:56.992123 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.036)       0:05:19.005 ******
2025-10-02 14:30:56.992170 | controller | skipping: [instance]
2025-10-02 14:30:56.992192 | controller |
2025-10-02 14:30:56.992321 | controller | TASK [sushy_emulator : Set instance_uuid variable for openstack driver] ********
2025-10-02 14:30:56.992446 | controller | Thursday 02 October 2025  14:30:56 +0000 (0:00:00.045)       0:05:19.050 ******
2025-10-02 14:30:57.011027 | controller | skipping: [instance]
2025-10-02 14:30:57.011127 | controller |
2025-10-02 14:30:57.011256 | controller | TASK [sushy_emulator : Base64 encode openstack clouds.yaml file] ***************
2025-10-02 14:30:57.011369 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.019)       0:05:19.069 ******
2025-10-02 14:30:57.030420 | controller | skipping: [instance]
2025-10-02 14:30:57.030503 | controller |
2025-10-02 14:30:57.030627 | controller | TASK [sushy_emulator : Generate htpasswd string] *******************************
2025-10-02 14:30:57.030752 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.019)       0:05:19.088 ******
2025-10-02 14:30:57.221582 | controller | changed: [instance]
2025-10-02 14:30:57.221714 | controller |
2025-10-02 14:30:57.221866 | controller | TASK [sushy_emulator : Write sushy emulator resource loop] *********************
2025-10-02 14:30:57.222066 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.190)       0:05:19.279 ******
2025-10-02 14:30:57.253265 | controller | skipping: [instance] => (item=secret)
2025-10-02 14:30:57.253371 | controller | skipping: [instance] => (item=configmap)
2025-10-02 14:30:57.253497 | controller | skipping: [instance] => (item=pod)
2025-10-02 14:30:57.253620 | controller | skipping: [instance] => (item=service)
2025-10-02 14:30:57.253727 | controller | skipping: [instance] => (item=route)
2025-10-02 14:30:57.253815 | controller | skipping: [instance]
2025-10-02 14:30:57.253905 | controller |
2025-10-02 14:30:57.254004 | controller | TASK [sushy_emulator : Write sushy emulator config] ****************************
2025-10-02 14:30:57.254131 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.032)       0:05:19.311 ******
2025-10-02 14:30:57.611404 | controller | changed: [instance]
2025-10-02 14:30:57.611464 | controller |
2025-10-02 14:30:57.611580 | controller | TASK [sushy_emulator : Write htpasswd string to file] **************************
2025-10-02 14:30:57.611692 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.358)       0:05:19.669 ******
2025-10-02 14:30:57.954470 | controller | changed: [instance]
2025-10-02 14:30:57.954524 | controller |
2025-10-02 14:30:57.954615 | controller | TASK [sushy_emulator : Create the sushy-emulator namespace] ********************
2025-10-02 14:30:57.954717 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.343)       0:05:20.012 ******
2025-10-02 14:30:57.974510 | controller | skipping: [instance]
2025-10-02 14:30:57.974580 | controller |
2025-10-02 14:30:57.974686 | controller | TASK [sushy_emulator : Check if router pod is running in openshift-ingress namespace] ***
2025-10-02 14:30:57.974803 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.020)       0:05:20.032 ******
2025-10-02 14:30:57.992936 | controller | skipping: [instance]
2025-10-02 14:30:57.993069 | controller |
2025-10-02 14:30:57.993175 | controller | TASK [sushy_emulator : Apply Sushy Emulator resources] *************************
2025-10-02 14:30:57.993297 | controller | Thursday 02 October 2025  14:30:57 +0000 (0:00:00.018)       0:05:20.051 ******
2025-10-02 14:30:58.021631 | controller | skipping: [instance] => (item=secret)
2025-10-02 14:30:58.021728 | controller | skipping: [instance] => (item=configmap)
2025-10-02 14:30:58.021852 | controller | skipping: [instance] => (item=service)
2025-10-02 14:30:58.021951 | controller | skipping: [instance] => (item=route)
2025-10-02 14:30:58.022072 | controller | skipping: [instance]
2025-10-02 14:30:58.022164 | controller |
2025-10-02 14:30:58.022279 | controller | TASK [sushy_emulator : Apply Sushy Emulator pod resource] **********************
2025-10-02 14:30:58.022376 | controller | Thursday 02 October 2025  14:30:58 +0000 (0:00:00.028)       0:05:20.079 ******
2025-10-02 14:30:58.040146 | controller | skipping: [instance]
2025-10-02 14:30:58.040266 | controller |
2025-10-02 14:30:58.040395 | controller | TASK [podman : Ensure podman is installed] *************************************
2025-10-02 14:30:58.040516 | controller | Thursday 02 October 2025  14:30:58 +0000 (0:00:00.018)       0:05:20.098 ******
2025-10-02 14:30:59.255482 | controller | ok: [instance]
2025-10-02 14:30:59.255771 | controller |
2025-10-02 14:30:59.480944 | controller | TASK [podman : Enable loginctl linger for ansible_user_id] *********************
2025-10-02 14:30:59.480974 | controller | Thursday 02 October 2025  14:30:59 +0000 (0:00:01.215)       0:05:21.313 ******
2025-10-02 14:30:59.480987 | controller | changed: [instance]
2025-10-02 14:30:59.509654 | controller |
2025-10-02 14:30:59.509680 | controller | TASK [podman : Ensure subordinate UID entry exists for zuul] *******************
2025-10-02 14:30:59.509688 | controller | Thursday 02 October 2025  14:30:59 +0000 (0:00:00.225)       0:05:21.538 ******
2025-10-02 14:30:59.509698 | controller | skipping: [instance]
2025-10-02 14:30:59.534909 | controller |
2025-10-02 14:30:59.534933 | controller | TASK [podman : Ensure subordinate GID entry exists for zuul] *******************
2025-10-02 14:30:59.534942 | controller | Thursday 02 October 2025  14:30:59 +0000 (0:00:00.028)       0:05:21.567 ******
2025-10-02 14:30:59.534954 | controller | skipping: [instance]
2025-10-02 14:30:59.567854 | controller |
2025-10-02 14:30:59.567888 | controller | TASK [podman : Run podman system migrate if subuid/subgid files were changed] ***
2025-10-02 14:30:59.567896 | controller | Thursday 02 October 2025  14:30:59 +0000 (0:00:00.025)       0:05:21.592 ******
2025-10-02 14:30:59.567907 | controller | skipping: [instance]
2025-10-02 14:31:06.083942 | controller |
2025-10-02 14:31:06.083997 | controller | TASK [sushy_emulator : Pull Sushy Emulator container image] ********************
2025-10-02 14:31:06.084006 | controller | Thursday 02 October 2025  14:30:59 +0000 (0:00:00.032)       0:05:21.625 ******
2025-10-02 14:31:06.084037 | controller | changed: [instance]
2025-10-02 14:31:06.933424 | controller |
2025-10-02 14:31:06.933466 | controller | TASK [sushy_emulator : Create and start Sushy Emulator container] **************
2025-10-02 14:31:06.933475 | controller | Thursday 02 October 2025  14:31:06 +0000 (0:00:06.515)       0:05:28.141 ******
2025-10-02 14:31:06.933486 | controller | changed: [instance]
2025-10-02 14:31:07.020571 | controller |
2025-10-02 14:31:07.020602 | controller | TASK [Verify connection to baremetal VMs via Sushy Emulator] *******************
2025-10-02 14:31:07.020616 | controller | Thursday 02 October 2025  14:31:06 +0000 (0:00:00.849)       0:05:28.990 ******
2025-10-02 14:31:07.020626 | controller |
2025-10-02 14:31:07.050503 | controller | TASK [sushy_emulator : Load baremetal hosts from libvirt_manager_bm_info_data fact] ***
2025-10-02 14:31:07.050530 | controller | Thursday 02 October 2025  14:31:07 +0000 (0:00:00.087)       0:05:29.078 ******
2025-10-02 14:31:07.050543 | controller | ok: [instance]
2025-10-02 14:31:07.077446 | controller |
2025-10-02 14:31:07.077472 | controller | TASK [sushy_emulator : Slurp content of: /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-10-02 14:31:07.077480 | controller | Thursday 02 October 2025  14:31:07 +0000 (0:00:00.029)       0:05:29.108 ******
2025-10-02 14:31:07.077491 | controller | skipping: [instance]
2025-10-02 14:31:07.103250 | controller |
2025-10-02 14:31:07.103278 | controller | TASK [sushy_emulator : Set cifmw_baremetal_hosts fact from /home/zuul/ci-framework-data/parameters/baremetal-info.yml] ***
2025-10-02 14:31:07.103286 | controller | Thursday 02 October 2025  14:31:07 +0000 (0:00:00.026)       0:05:29.135 ******
2025-10-02 14:31:07.103296 | controller | skipping: [instance]
2025-10-02 14:31:08.133065 | controller |
2025-10-02 14:31:08.133101 | controller | TASK [sushy_emulator : Test Sushy Emulator and connection to hypervisor libvirt socket] ***
2025-10-02 14:31:08.133111 | controller | Thursday 02 October 2025  14:31:07 +0000 (0:00:00.025)       0:05:29.161 ******
2025-10-02 14:31:08.133126 | controller | ok: [instance]
2025-10-02 14:31:08.133149 | controller |
2025-10-02 14:31:08.133246 | controller | TASK [sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator] ***
2025-10-02 14:31:08.133362 | controller | Thursday 02 October 2025  14:31:08 +0000 (0:00:01.026)       0:05:30.187 ******
2025-10-02 14:31:10.093585 | controller | ok: [instance] => (item=1b5dbafc-50eb-41fa-8629-9e9eacd521f4)
2025-10-02 14:31:10.093634 | controller | ok: [instance] => (item=8c40e17f-cb95-4fa5-9e67-d663e3fe4bb0)
2025-10-02 14:31:10.093644 | controller |
2025-10-02 14:31:10.093786 | controller | TASK [sushy_emulator : Verify baremetal VM power status] ***********************
2025-10-02 14:31:10.157809 | controller | Thursday 02 October 2025  14:31:10 +0000 (0:00:01.963)       0:05:32.151 ******
2025-10-02 14:31:10.157838 | controller | ok: [instance] => (item=cifmw-compute-0)
2025-10-02 14:31:10.159095 | controller | ok: [instance] => (item=cifmw-compute-1)
2025-10-02 14:31:10.159113 | controller |
2025-10-02 14:31:10.159263 | controller | PLAY RECAP *********************************************************************
2025-10-02 14:31:10.159273 | controller | instance                   : ok=228  changed=86   unreachable=0    failed=0    skipped=105  rescued=0    ignored=0
2025-10-02 14:31:10.159279 | controller |
2025-10-02 14:31:10.159285 | controller | Thursday 02 October 2025  14:31:10 +0000 (0:00:00.064)       0:05:32.215 ******
2025-10-02 14:31:10.159290 | controller | ===============================================================================
2025-10-02 14:31:10.159295 | controller | sushy_emulator : Check if router pod is running in openshift-ingress namespace - 191.45s
2025-10-02 14:31:10.159300 | controller | sushy_emulator : Apply Sushy Emulator pod resource --------------------- 30.72s
2025-10-02 14:31:10.159306 | controller | libvirt_manager : Install packages required for using KVM -------------- 14.09s
2025-10-02 14:31:10.159311 | controller | sushy_emulator : Pull Sushy Emulator container image -------------------- 6.52s
2025-10-02 14:31:10.159316 | controller | ci_nmstate : Install required packages on instance ---------------------- 4.64s
2025-10-02 14:31:10.159321 | controller | sushy_emulator : Install required packages ------------------------------ 4.03s
2025-10-02 14:31:10.159326 | controller | dnsmasq : Ensure SELinux knows about the new files and directories ------ 3.83s
2025-10-02 14:31:10.159334 | controller | sushy_emulator : Apply Sushy Emulator resources ------------------------- 2.68s
2025-10-02 14:31:10.160064 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 2.49s
2025-10-02 14:31:10.160265 | controller | sushy_emulator : Verify connection to baremetal VMs via Sushy Emulator --- 1.96s
2025-10-02 14:31:10.160276 | controller | ci_nmstate : Apply the desidered state on instance ---------------------- 1.95s
2025-10-02 14:31:10.160282 | controller | sushy_emulator : Write sushy emulator resource loop --------------------- 1.90s
2025-10-02 14:31:10.160293 | controller | libvirt_manager : Restart firewalld ------------------------------------- 1.71s
2025-10-02 14:31:10.160298 | controller | dnsmasq : Reload dnsmasq ------------------------------------------------ 1.41s
2025-10-02 14:31:10.160303 | controller | dnsmasq : Add/Remove address -------------------------------------------- 1.37s
2025-10-02 14:31:10.160308 | controller | sushy_emulator : Install required packages ------------------------------ 1.27s
2025-10-02 14:31:10.160316 | controller | dnsmasq : Install needed packages --------------------------------------- 1.24s
2025-10-02 14:31:10.160338 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.23s
2025-10-02 14:31:10.160523 | controller | podman : Ensure podman is installed ------------------------------------- 1.22s
2025-10-02 14:31:10.251806 | controller | sushy_emulator : Allow Sushy Emulator key ------------------------------- 1.15s
2025-10-02 14:31:10.251838 | controller | INFO     Running default > cleanup
2025-10-02 14:31:10.252275 | controller | WARNING  Skipping, cleanup playbook not configured.
2025-10-02 14:31:10.252862 | controller | INFO     Writing /tmp/report.html report.
2025-10-02 14:31:10.380564 | [controller] Waiting on logger
2025-10-02 14:31:15.552884 | [controller] Waiting on logger
2025-10-02 14:31:25.984882 | [controller] Waiting on logger
2025-10-02 14:31:36.416827 | [controller] Waiting on logger
2025-10-02 14:31:40.337825 | [Zuul] Log Stream did not terminate
2025-10-02 14:31:40.338000 | controller | changed
2025-10-02 14:31:40.365535 | 
2025-10-02 14:31:40.365591 | PLAY RECAP
2025-10-02 14:31:40.365631 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-02 14:31:40.365654 | 
2025-10-02 14:31:40.424221 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-02 14:31:40.425021 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-02 14:31:40.938199 | 
2025-10-02 14:31:40.938301 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-10-02 14:31:40.958126 | 
2025-10-02 14:31:40.958223 | TASK [Filter out host if needed]
2025-10-02 14:31:40.966556 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-10-02 14:31:40.970929 | 
2025-10-02 14:31:40.970998 | TASK [Ensure file is present]
2025-10-02 14:31:41.333192 | controller | ok
2025-10-02 14:31:41.339774 | 
2025-10-02 14:31:41.339852 | TASK [Manage molecule report file]
2025-10-02 14:31:41.359970 | [controller] Waiting on logger
2025-10-02 14:31:50.752936 | [controller] Waiting on logger
2025-10-02 14:32:01.184951 | [controller] Waiting on logger
2025-10-02 14:32:10.528888 | [controller] Waiting on logger
2025-10-02 14:32:11.721749 | [Zuul] Log Stream did not terminate
2025-10-02 14:32:11.721998 | controller | changed
2025-10-02 14:32:11.727260 | 
2025-10-02 14:32:11.727323 | TASK [Check if we get ci-framework-data basedir]
2025-10-02 14:32:11.998972 | controller | ok
2025-10-02 14:32:12.003885 | 
2025-10-02 14:32:12.003946 | TASK [Create ci-framework-data log directory for zuul]
2025-10-02 14:32:12.366668 | controller | changed
2025-10-02 14:32:12.371805 | 
2025-10-02 14:32:12.371869 | TASK [Copy ci-framework interesting files]
2025-10-02 14:32:12.392659 | [controller] Waiting on logger
2025-10-02 14:32:22.816857 | [controller] Waiting on logger
2025-10-02 14:32:33.248877 | [controller] Waiting on logger
2025-10-02 14:32:42.594009 | [controller] Waiting on logger
2025-10-02 14:32:42.643466 | [Zuul] Log Stream did not terminate
2025-10-02 14:32:42.643577 | controller | changed
2025-10-02 14:32:42.648750 | 
2025-10-02 14:32:42.648828 | TASK [Get SELinux listing]
2025-10-02 14:32:43.680993 | [controller] Waiting on logger
2025-10-02 14:33:03.264922 | [controller] Waiting on logger
2025-10-02 14:33:03.392923 | [controller] Waiting on logger
2025-10-02 14:33:12.940446 | [Zuul] Log Stream did not terminate
2025-10-02 14:33:12.940650 | controller | changed
2025-10-02 14:33:12.946239 | 
2025-10-02 14:33:12.946306 | TASK [Generate log index]
2025-10-02 14:33:14.010488 | controller | changed
2025-10-02 14:33:14.015182 | 
2025-10-02 14:33:14.015247 | TASK [Get some env related data]
2025-10-02 14:33:14.035830 | [controller] Waiting on logger
2025-10-02 14:33:23.397736 | [controller] Waiting on logger
2025-10-02 14:33:33.792932 | [controller] Waiting on logger
2025-10-02 14:33:44.225053 | [controller] Waiting on logger
2025-10-02 14:33:45.340123 | [Zuul] Log Stream did not terminate
2025-10-02 14:33:45.340281 | controller | changed
2025-10-02 14:33:45.345286 | 
2025-10-02 14:33:45.345347 | TASK [Generate list of logs to collect in home directory]
2025-10-02 14:33:45.716609 | controller | ok: All paths examined
2025-10-02 14:33:45.721677 | 
2025-10-02 14:33:45.721736 | LOOP [Copy logs from home directory]
2025-10-02 14:33:46.252548 | controller | changed:
2025-10-02 14:33:46.252801 | controller | {
2025-10-02 14:33:46.252840 | controller |   "atime": 1743544925.4788878,
2025-10-02 14:33:46.252867 | controller |   "ctime": 1743545329.1409318,
2025-10-02 14:33:46.252892 | controller |   "dev": 64513,
2025-10-02 14:33:46.252914 | controller |   "gid": 1000,
2025-10-02 14:33:46.252936 | controller |   "gr_name": "zuul",
2025-10-02 14:33:46.252956 | controller |   "inode": 4518807,
2025-10-02 14:33:46.253066 | controller |   "isblk": false,
2025-10-02 14:33:46.253095 | controller |   "ischr": false,
2025-10-02 14:33:46.253112 | controller |   "isdir": false,
2025-10-02 14:33:46.253126 | controller |   "isfifo": false,
2025-10-02 14:33:46.253144 | controller |   "isgid": false,
2025-10-02 14:33:46.253158 | controller |   "islnk": false,
2025-10-02 14:33:46.253172 | controller |   "isreg": true,
2025-10-02 14:33:46.253186 | controller |   "issock": false,
2025-10-02 14:33:46.253200 | controller |   "isuid": false,
2025-10-02 14:33:46.253214 | controller |   "mode": "0644",
2025-10-02 14:33:46.253228 | controller |   "mtime": 1743545329.1409318,
2025-10-02 14:33:46.253242 | controller |   "nlink": 1,
2025-10-02 14:33:46.253256 | controller |   "path": "/home/zuul/crc-setup.log",
2025-10-02 14:33:46.253270 | controller |   "pw_name": "zuul",
2025-10-02 14:33:46.253283 | controller |   "rgrp": true,
2025-10-02 14:33:46.253297 | controller |   "roth": true,
2025-10-02 14:33:46.253310 | controller |   "rusr": true,
2025-10-02 14:33:46.253323 | controller |   "size": 4108,
2025-10-02 14:33:46.253335 | controller |   "uid": 1000,
2025-10-02 14:33:46.253348 | controller |   "wgrp": false,
2025-10-02 14:33:46.253361 | controller |   "woth": false,
2025-10-02 14:33:46.253374 | controller |   "wusr": true,
2025-10-02 14:33:46.253422 | controller |   "xgrp": false,
2025-10-02 14:33:46.253440 | controller |   "xoth": false,
2025-10-02 14:33:46.253455 | controller |   "xusr": false
2025-10-02 14:33:46.253469 | controller | }
2025-10-02 14:33:46.769536 | controller | changed:
2025-10-02 14:33:46.769629 | controller | {
2025-10-02 14:33:46.769655 | controller |   "atime": 1743545331.0429637,
2025-10-02 14:33:46.769676 | controller |   "ctime": 1743545842.0111232,
2025-10-02 14:33:46.769693 | controller |   "dev": 64513,
2025-10-02 14:33:46.769710 | controller |   "gid": 1000,
2025-10-02 14:33:46.769726 | controller |   "gr_name": "zuul",
2025-10-02 14:33:46.769742 | controller |   "inode": 4194437,
2025-10-02 14:33:46.769756 | controller |   "isblk": false,
2025-10-02 14:33:46.769770 | controller |   "ischr": false,
2025-10-02 14:33:46.769796 | controller |   "isdir": false,
2025-10-02 14:33:46.769812 | controller |   "isfifo": false,
2025-10-02 14:33:46.769826 | controller |   "isgid": false,
2025-10-02 14:33:46.769840 | controller |   "islnk": false,
2025-10-02 14:33:46.769853 | controller |   "isreg": true,
2025-10-02 14:33:46.769868 | controller |   "issock": false,
2025-10-02 14:33:46.769884 | controller |   "isuid": false,
2025-10-02 14:33:46.769899 | controller |   "mode": "0644",
2025-10-02 14:33:46.769914 | controller |   "mtime": 1743545842.0111232,
2025-10-02 14:33:46.769928 | controller |   "nlink": 1,
2025-10-02 14:33:46.769943 | controller |   "path": "/home/zuul/crc-start.log",
2025-10-02 14:33:46.769957 | controller |   "pw_name": "zuul",
2025-10-02 14:33:46.769971 | controller |   "rgrp": true,
2025-10-02 14:33:46.769986 | controller |   "roth": true,
2025-10-02 14:33:46.770000 | controller |   "rusr": true,
2025-10-02 14:33:46.770014 | controller |   "size": 4023,
2025-10-02 14:33:46.770028 | controller |   "uid": 1000,
2025-10-02 14:33:46.770042 | controller |   "wgrp": false,
2025-10-02 14:33:46.770055 | controller |   "woth": false,
2025-10-02 14:33:46.770069 | controller |   "wusr": true,
2025-10-02 14:33:46.770082 | controller |   "xgrp": false,
2025-10-02 14:33:46.770097 | controller |   "xoth": false,
2025-10-02 14:33:46.770111 | controller |   "xusr": false
2025-10-02 14:33:46.770126 | controller | }
2025-10-02 14:33:47.302164 | controller | changed:
2025-10-02 14:33:47.302254 | controller | {
2025-10-02 14:33:47.302279 | controller |   "atime": 1759414862.9693742,
2025-10-02 14:33:47.302298 | controller |   "ctime": 1759414878.5126307,
2025-10-02 14:33:47.302315 | controller |   "dev": 64513,
2025-10-02 14:33:47.302331 | controller |   "gid": 1000,
2025-10-02 14:33:47.302346 | controller |   "gr_name": "zuul",
2025-10-02 14:33:47.302363 | controller |   "inode": 4233412,
2025-10-02 14:33:47.302379 | controller |   "isblk": false,
2025-10-02 14:33:47.302425 | controller |   "ischr": false,
2025-10-02 14:33:47.302444 | controller |   "isdir": false,
2025-10-02 14:33:47.302459 | controller |   "isfifo": false,
2025-10-02 14:33:47.302474 | controller |   "isgid": false,
2025-10-02 14:33:47.302489 | controller |   "islnk": false,
2025-10-02 14:33:47.302502 | controller |   "isreg": true,
2025-10-02 14:33:47.302516 | controller |   "issock": false,
2025-10-02 14:33:47.302529 | controller |   "isuid": false,
2025-10-02 14:33:47.302542 | controller |   "mode": "0644",
2025-10-02 14:33:47.302555 | controller |   "mtime": 1759414878.5126307,
2025-10-02 14:33:47.302568 | controller |   "nlink": 1,
2025-10-02 14:33:47.302581 | controller |   "path": "/home/zuul/ansible.log",
2025-10-02 14:33:47.302596 | controller |   "pw_name": "zuul",
2025-10-02 14:33:47.302609 | controller |   "rgrp": true,
2025-10-02 14:33:47.302622 | controller |   "roth": true,
2025-10-02 14:33:47.302635 | controller |   "rusr": true,
2025-10-02 14:33:47.302648 | controller |   "size": 6749,
2025-10-02 14:33:47.302661 | controller |   "uid": 1000,
2025-10-02 14:33:47.302674 | controller |   "wgrp": false,
2025-10-02 14:33:47.302687 | controller |   "woth": false,
2025-10-02 14:33:47.302700 | controller |   "wusr": true,
2025-10-02 14:33:47.302713 | controller |   "xgrp": false,
2025-10-02 14:33:47.302726 | controller |   "xoth": false,
2025-10-02 14:33:47.302738 | controller |   "xusr": false
2025-10-02 14:33:47.302751 | controller | }
2025-10-02 14:33:47.317664 | 
2025-10-02 14:33:47.317765 | TASK [Copy crio stats log file]
2025-10-02 14:33:47.330822 | controller | skipping: Conditional result was False
2025-10-02 14:33:47.335990 | 
2025-10-02 14:33:47.336054 | TASK [Get SELinux related data]
2025-10-02 14:33:48.384887 | [controller] Waiting on logger
2025-10-02 14:33:58.817063 | [controller] Waiting on logger
2025-10-02 14:34:09.248999 | [controller] Waiting on logger
2025-10-02 14:34:17.627232 | [Zuul] Log Stream did not terminate
2025-10-02 14:34:17.627483 | controller | ERROR
2025-10-02 14:34:17.627595 | controller | {
2025-10-02 14:34:17.627637 | controller |   "delta": "0:00:00.008833",
2025-10-02 14:34:17.627663 | controller |   "end": "2025-10-02 14:33:47.601772",
2025-10-02 14:34:17.627684 | controller |   "msg": "non-zero return code",
2025-10-02 14:34:17.627703 | controller |   "rc": 1,
2025-10-02 14:34:17.627722 | controller |   "start": "2025-10-02 14:33:47.592939"
2025-10-02 14:34:17.627740 | controller | }
2025-10-02 14:34:17.627765 | controller | ERROR: Ignoring Errors
2025-10-02 14:34:17.632989 | 
2025-10-02 14:34:17.633054 | TASK [Create system configuration directory]
2025-10-02 14:34:17.905498 | controller | changed
2025-10-02 14:34:17.910130 | 
2025-10-02 14:34:17.910193 | TASK [Get some of the system configurations]
2025-10-02 14:34:18.592978 | [controller] Waiting on logger
2025-10-02 14:34:22.934761 | controller | changed
2025-10-02 14:34:22.939892 | 
2025-10-02 14:34:22.939955 | TASK [Copy generated documentation if available]
2025-10-02 14:34:22.953572 | controller | skipping: Conditional result was False
2025-10-02 14:34:22.958591 | 
2025-10-02 14:34:22.958652 | TASK [Copy generated AsciiDoc documentation if available]
2025-10-02 14:34:22.971145 | controller | skipping: Conditional result was False
2025-10-02 14:34:22.976167 | 
2025-10-02 14:34:22.976228 | TASK [Compress logs bigger than 2MB]
2025-10-02 14:34:22.997789 | [controller] Waiting on logger
2025-10-02 14:34:29.262855 | controller | changed
2025-10-02 14:34:29.268047 | 
2025-10-02 14:34:29.268113 | TASK [Copy files from workspace on node]
2025-10-02 14:34:29.286483 | controller | ok
2025-10-02 14:34:29.318852 | 
2025-10-02 14:34:29.318922 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-02 14:34:29.342508 | controller | skipping: Conditional result was False
2025-10-02 14:34:29.349586 | 
2025-10-02 14:34:29.349678 | TASK [fetch-output : Set log path for single node]
2025-10-02 14:34:29.378263 | controller | ok
2025-10-02 14:34:29.383121 | 
2025-10-02 14:34:29.383190 | LOOP [fetch-output : Ensure local output dirs]
2025-10-02 14:34:29.574749 | controller -> localhost | ok: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/logs"
2025-10-02 14:34:29.574974 | controller -> localhost | changed: All items complete
2025-10-02 14:34:29.575005 | 
2025-10-02 14:34:29.751071 | controller -> localhost | changed: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/artifacts"
2025-10-02 14:34:29.923002 | controller -> localhost | changed: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/docs"
2025-10-02 14:34:29.930683 | 
2025-10-02 14:34:29.930749 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-02 14:34:30.536323 | controller | changed:
2025-10-02 14:34:30.536531 | controller | .d..t...... ./
2025-10-02 14:34:30.536563 | controller | >f+++++++++ README.html
2025-10-02 14:34:30.536587 | controller | >f+++++++++ ansible-execution.log
2025-10-02 14:34:30.536608 | controller | >f+++++++++ ansible.log
2025-10-02 14:34:30.536628 | controller | >f+++++++++ crc-setup.log
2025-10-02 14:34:30.536647 | controller | >f+++++++++ crc-start.log
2025-10-02 14:34:30.536666 | controller | >f+++++++++ dmesg.log
2025-10-02 14:34:30.536684 | controller | >f+++++++++ installed-pkgs.log
2025-10-02 14:34:30.536702 | controller | >f+++++++++ python.log
2025-10-02 14:34:30.536720 | controller | >f+++++++++ registries.conf
2025-10-02 14:34:30.536737 | controller | >f+++++++++ report.html
2025-10-02 14:34:30.536754 | controller | >f+++++++++ selinux-denials.log
2025-10-02 14:34:30.536771 | controller | >f+++++++++ selinux-listing.log
2025-10-02 14:34:30.536797 | controller | cd+++++++++ ci-framework-data/
2025-10-02 14:34:30.536815 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-10-02 14:34:30.536833 | controller | >f+++++++++ ci-framework-data/artifacts/debug_cifmw_libvirt_manager_layout.yml
2025-10-02 14:34:30.536850 | controller | >f+++++++++ ci-framework-data/artifacts/debug_network_data.yml
2025-10-02 14:34:30.536868 | controller | >f+++++++++ ci-framework-data/artifacts/debug_pub_net_value.txt
2025-10-02 14:34:30.536887 | controller | >f+++++++++ ci-framework-data/artifacts/interfaces-info.yml
2025-10-02 14:34:30.536904 | controller | >f+++++++++ ci-framework-data/artifacts/libvirt-uuids.yml
2025-10-02 14:34:30.536921 | controller | >f+++++++++ ci-framework-data/artifacts/net-map-def-patch.yml
2025-10-02 14:34:30.536939 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-10-02 14:34:30.536956 | controller | cd+++++++++ ci-framework-data/artifacts/nmstate/
2025-10-02 14:34:30.536973 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-final-state.yaml
2025-10-02 14:34:30.536990 | controller | >f+++++++++ ci-framework-data/artifacts/nmstate/instance-state.yaml
2025-10-02 14:34:30.537008 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-10-02 14:34:30.537026 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-10-02 14:34:30.537043 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-10-02 14:34:30.537060 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-10-02 14:34:30.537078 | controller | cd+++++++++ ci-framework-data/artifacts/sushy_emulator/
2025-10-02 14:34:30.537096 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/.htpasswd
2025-10-02 14:34:30.537114 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/config.conf
2025-10-02 14:34:30.537131 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/configmap.yaml
2025-10-02 14:34:30.537148 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/known_hosts
2025-10-02 14:34:30.537165 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/pod.yaml
2025-10-02 14:34:30.537182 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/route.yaml
2025-10-02 14:34:30.537199 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/secret.yaml
2025-10-02 14:34:30.537220 | controller | >f+++++++++ ci-framework-data/artifacts/sushy_emulator/service.yaml
2025-10-02 14:34:30.537239 | controller | cd+++++++++ ci-framework-data/logs/
2025-10-02 14:34:30.537256 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-10-02 14:34:30.537274 | controller | cd+++++++++ registries.conf.d/
2025-10-02 14:34:30.537291 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-10-02 14:34:30.537309 | controller | cd+++++++++ system-config/
2025-10-02 14:34:30.537326 | controller | cd+++++++++ system-config/libvirt/
2025-10-02 14:34:30.537343 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-10-02 14:34:30.537361 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-10-02 14:34:30.537414 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-10-02 14:34:30.537442 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-10-02 14:34:30.537462 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-10-02 14:34:30.537480 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-10-02 14:34:30.537498 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-10-02 14:34:30.537516 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-10-02 14:34:30.537533 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-10-02 14:34:30.537551 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-10-02 14:34:30.537568 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-10-02 14:34:30.537586 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-10-02 14:34:30.537603 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-10-02 14:34:30.537619 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-10-02 14:34:30.537635 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-10-02 14:34:30.537652 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-10-02 14:34:30.976565 | controller | changed: .d..t...... ./
2025-10-02 14:34:31.072861 | [controller] Waiting on logger
2025-10-02 14:34:31.405055 | controller | changed: .d..t...... ./
2025-10-02 14:34:31.416001 | 
2025-10-02 14:34:31.416063 | TASK [Return artifact to Zuul]
2025-10-02 14:34:31.455416 | controller | ok
2025-10-02 14:34:31.474147 | 
2025-10-02 14:34:31.474209 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-10-02 14:34:31.474312 | 
2025-10-02 14:34:31.474339 | PLAY RECAP
2025-10-02 14:34:31.474379 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-10-02 14:34:31.474421 | 
2025-10-02 14:34:31.568104 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-02 14:34:31.568834 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 14:34:32.141801 | 
2025-10-02 14:34:32.141991 | PLAY [all]
2025-10-02 14:34:32.162273 | 
2025-10-02 14:34:32.162373 | TASK [include_role : fetch-output]
2025-10-02 14:34:32.194303 | controller | ok
2025-10-02 14:34:32.212650 | 
2025-10-02 14:34:32.212766 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-02 14:34:32.259627 | controller | skipping: Conditional result was False
2025-10-02 14:34:32.266452 | 
2025-10-02 14:34:32.266552 | TASK [fetch-output : Set log path for single node]
2025-10-02 14:34:32.298706 | controller | ok
2025-10-02 14:34:32.304306 | 
2025-10-02 14:34:32.304434 | LOOP [fetch-output : Ensure local output dirs]
2025-10-02 14:34:32.635262 | controller -> localhost | ok: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/logs"
2025-10-02 14:34:32.825541 | controller -> localhost | ok: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/artifacts"
2025-10-02 14:34:33.033999 | controller -> localhost | ok: "/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/docs"
2025-10-02 14:34:33.050598 | 
2025-10-02 14:34:33.050788 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-02 14:34:33.646223 | controller | ok
2025-10-02 14:34:33.646576 | controller | ok: All items complete
2025-10-02 14:34:33.646618 | 
2025-10-02 14:34:34.081439 | controller | ok
2025-10-02 14:34:34.527742 | controller | ok
2025-10-02 14:34:34.547962 | 
2025-10-02 14:34:34.548032 | TASK [include_role : fetch-output-openshift]
2025-10-02 14:34:34.562654 | controller | skipping: Conditional result was False
2025-10-02 14:34:34.568337 | 
2025-10-02 14:34:34.568423 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-02 14:34:34.965937 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.008845
2025-10-02 14:34:35.158442 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007316
2025-10-02 14:34:35.186822 | 
2025-10-02 14:34:35.186895 | PLAY [all]
2025-10-02 14:34:35.200773 | 
2025-10-02 14:34:35.200852 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-02 14:34:35.680024 | controller | changed
2025-10-02 14:34:35.702102 | 
2025-10-02 14:34:35.702164 | PLAY RECAP
2025-10-02 14:34:35.702216 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-02 14:34:35.702239 | 
2025-10-02 14:34:35.805035 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 14:34:35.805838 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-02 14:34:36.351324 | 
2025-10-02 14:34:36.351448 | PLAY [localhost]
2025-10-02 14:34:36.368454 | 
2025-10-02 14:34:36.368531 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-02 14:34:36.691875 | localhost | changed
2025-10-02 14:34:36.696534 | 
2025-10-02 14:34:36.696614 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-02 14:34:36.724909 | localhost | ok
2025-10-02 14:34:36.732873 | 
2025-10-02 14:34:36.732946 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-02 14:34:37.036163 | localhost | changed
2025-10-02 14:34:37.042206 | 
2025-10-02 14:34:37.042284 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-02 14:34:37.618484 | localhost | changed
2025-10-02 14:34:37.623434 | 
2025-10-02 14:34:37.623503 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-02 14:34:37.967002 | localhost | Identity added: /var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/tmp/ansible.7d46zj8f (/var/lib/zuul/builds/6434172efb564516ab8f10a28e69c8ca/work/tmp/ansible.7d46zj8f)
2025-10-02 14:34:37.967268 | localhost | ok: Runtime: 0:00:00.007277
2025-10-02 14:34:37.971741 | 
2025-10-02 14:34:37.971834 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-02 14:34:38.215749 | localhost | ok: Runtime: 0:00:00.005994
2025-10-02 14:34:38.220863 | 
2025-10-02 14:34:38.220935 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-02 14:34:38.283734 | localhost | changed
2025-10-02 14:34:38.288149 | 
2025-10-02 14:34:38.288222 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-02 14:34:38.654290 | localhost | changed
2025-10-02 14:34:38.675159 | 
2025-10-02 14:34:38.675221 | PLAY [localhost]
2025-10-02 14:34:38.686190 | 
2025-10-02 14:34:38.686254 | TASK [Generate bulk log download script]
2025-10-02 14:34:38.704398 | localhost | ok
2025-10-02 14:34:38.717932 | 
2025-10-02 14:34:38.718084 | TASK [local-log-download : Check API endpoint is defined]
2025-10-02 14:34:38.746943 | localhost | ok: All assertions passed
2025-10-02 14:34:38.751398 | 
2025-10-02 14:34:38.751466 | TASK [local-log-download : Create download script]
2025-10-02 14:34:39.110152 | localhost -> localhost | changed
2025-10-02 14:34:39.119142 | 
2025-10-02 14:34:39.119210 | TASK [Register quick-download link]
2025-10-02 14:34:39.147970 | localhost | ok
2025-10-02 14:34:39.187108 | 
2025-10-02 14:34:39.187196 | PLAY [logserver.rdoproject.org]
2025-10-02 14:34:39.196751 | 
2025-10-02 14:34:39.196832 | TASK [Set zuul-log-path fact]
2025-10-02 14:34:39.214107 | logserver.rdoproject.org | ok
2025-10-02 14:34:39.222974 | 
2025-10-02 14:34:39.223043 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 14:34:39.249629 | logserver.rdoproject.org | ok
2025-10-02 14:34:39.254937 | 
2025-10-02 14:34:39.255005 | TASK [upload-logs : Create log directories]
2025-10-02 14:34:41.096547 | logserver.rdoproject.org | changed
2025-10-02 14:34:41.099493 | 
2025-10-02 14:34:41.099557 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-02 14:34:41.335758 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004676
2025-10-02 14:34:41.340722 | 
2025-10-02 14:34:41.340819 | TASK [upload-logs : Upload logs to log server]
2025-10-02 14:34:42.855477 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-02 14:34:42.858236 | 
2025-10-02 14:34:42.858303 | LOOP [upload-logs : Compress console log and json output]
2025-10-02 14:34:42.894142 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 14:34:42.902484 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 14:34:42.915078 | 
2025-10-02 14:34:42.915180 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-02 14:34:42.947458 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 14:34:42.947666 | 
2025-10-02 14:34:42.950861 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 14:34:42.961601 | 
2025-10-02 14:34:42.961678 | LOOP [upload-logs : Upload console log and json output]